Network debugging

High packet loss

But maybe data is getting through. Well, some data, anyway. Consider this ping session:

PING freefall.FreeBSD.org (216.136.204.21): 56 data bytes
64 bytes from 216.136.204.21: icmp_seq=0 ttl=244 time=496.426 ms
64 bytes from 216.136.204.21: icmp_seq=1 ttl=244 time=491.334 ms
64 bytes from 216.136.204.21: icmp_seq=2 ttl=244 time=479.077 ms
64 bytes from 216.136.204.21: icmp_seq=3 ttl=244 time=473.774 ms
64 bytes from 216.136.204.21: icmp_seq=4 ttl=244 time=733.429 ms
64 bytes from 216.136.204.21: icmp_seq=5 ttl=244 time=644.726 ms
64 bytes from 216.136.204.21: icmp_seq=7 ttl=244 time=490.331 ms
64 bytes from 216.136.204.21: icmp_seq=8 ttl=244 time=839.671 ms
64 bytes from 216.136.204.21: icmp_seq=9 ttl=244 time=773.764 ms
64 bytes from 216.136.204.21: icmp_seq=10 ttl=244 time=553.067 ms
64 bytes from 216.136.204.21: icmp_seq=11 ttl=244 time=454.707 ms
64 bytes from 216.136.204.21: icmp_seq=12 ttl=244 time=472.212 ms
64 bytes from 216.136.204.21: icmp_seq=13 ttl=244 time=448.322 ms
64 bytes from 216.136.204.21: icmp_seq=14 ttl=244 time=441.352 ms
64 bytes from 216.136.204.21: icmp_seq=15 ttl=244 time=455.595 ms
64 bytes from 216.136.204.21: icmp_seq=16 ttl=244 time=460.040 ms
64 bytes from 216.136.204.21: icmp_seq=17 ttl=244 time=476.943 ms
64 bytes from 216.136.204.21: icmp_seq=18 ttl=244 time=514.615 ms
64 bytes from 216.136.204.21: icmp_seq=23 ttl=244 time=538.232 ms
64 bytes from 216.136.204.21: icmp_seq=24 ttl=244 time=444.123 ms
64 bytes from 216.136.204.21: icmp_seq=25 ttl=244 time=449.075 ms
?C
--- 216.136.204.21 ping statistics ---
27 packets transmitted, 21 packets received, 22% packet loss
round-trip min/avg/max/stddev = 441.352/530.039/839.671/113.674 ms

In this case, we have a connection. But look carefully at those sequence numbers. At one point, four packets in a row (sequence 19 to 22) get lost. How high a packet drop rate is still acceptable? 1% or 2% is probably still (barely) acceptable. By the time you get to 10%, though, things look a lot worse. 10% packet drop rate doesn't mean that your connection slows down by 10%. For every dropped packet, you have a minimum delay of one second until TCP retries it. If that retried packet gets dropped too—which it will every 10 dropped packets if you have a 10% drop rate—the second retry takes another three seconds. If you're transmitting packets of 64 bytes over a 33.6 kb/s link, you can normally get about 60 packets through per second. With 10% packet loss, the time to get these packets through is about eight seconds, a throughput loss of 87.5%.

With 20% packet loss, the results are even more dramatic. Now 12 of the 60 packets have to be retried, and 2.4 of them will be retried a second time (for three seconds delay), and 0.48 of them will be retried a third time (six seconds delay). This makes a total of 22 seconds delay, a through put degradation of nearly 96%.

Theoretically, you might think that the degradation would not be as bad for big packets, such as you might have with file transfers with ftp. In fact, the situation is worse then: in most cases the packet drop rate rises sharply with the packet size, and it's common enough that ftp times out completely before it can transfer a file.

To get a better over view of what's going on, let's look at another program, tcpdump.

tcpdump

tcpdump is a program that monitors a network interface and displays selected information that passes through it. It uses the BerkeleyPacketFilter (bpf), an optional component of the kernel. It's included in recent versions of the GENERIC kernel, but it's possible to remove it. If you don't configure the BerkeleyPacketFilter, you get a message like:

tcpdump:  /dev/bpf0:  device not configured

tcpdump poses a potential security problem: you can use it to read anything that goes over the network. As a result, you must be root to run it. The simplest way to run it is without any parameters. This causes tcpdump to monitor and display all traffic on the first active network interface, normally Ethernet:

# tcpdump
tcpdump: listening on ep0
1: 13:27:57.757157 arp who-has wait.example.org tell presto.example.org
2: 13:28:06.740047 0:4c:a5:0:0:0 2:0:0:0:45:0 4011 80:
             c93c c06d c589 c06d c5ff 007b 007b 0038
             5ccb 1d03 06ee 0000 5613 0000 1093 cb15
             2512 b7e2 de6b 0ead c000 0000 0000 0000
             0000 0000 0000
3: 13:28:06.740117 freebie.example.org.ntp > 223.147.37.255.ntp: v3 bcast strat 3 p oll 6  prec -18
4: 13:28:08.004715 arp who-has wait.example.org tell presto.example.org
5: 13:28:10.987453 bumble.example.org.who > 223.147.37.255.who: udp 84
6: 13:28:13.790106 freebie.example.org.6000 > presto.example.org.1089: P 536925467:
536925851(384) ack 325114346 win 17280 <nop,nop,timestamp 155186 1163778,nop,no
p,[|tcp]> (DF)
7: 13:28:13.934336 arp who-has freebie.example.org tell presto.example.org
8: 13:28:13.934444 arp reply freebie.example.org is-at 0:a0:24:37:d:2b
9: 13:28:13.935903 presto.example.org.1089 > freebie.example.org.6000:  . ack 536925
851 win 16896 <nop,nop,timestamp 1190189 155186,nop,nop,[|tcp]> (DF)
10: 13:28:13.936313 freebie.example.org.6000 > presto.example.org.1089: P 536925851
:536926299(448) ack 325114346 win 17280 <nop,nop,timestamp 155186 1190189,nop,no
p,[|tcp]> (DF)

This output looks confusing at first. Let's look at it in more detail:

• The first message shows the interface on which tcpdump listens. By default, it is the first running interface that it finds. tcpdump searches the list of interfaces in the sequence that ifconfig -a displays. Generally you can assume that it will find the primary Ethernet interface. If you want to listen on another interface, specify it on the command line. For example, to listen on a PPP interface, you would enter

  # tcpdump -i tun0
  
• At the beginning of each message is a timestamp, with a resolution of 1 /s. These times are relatively accurate; you'll frequently see time differences of less than 1 ms. In this example, the last two messages are 108 ms apart. These times are important: a lot of network problems are performance problems, and there's a big difference in performance between a net where a reply takes 100 ms sand one in which a reply takes 100 ms.
• To make things easier, I have put a line number in italics at the beginning of each line. It doesn't appear in the tcpdump printout.
• Line 1 shows an ARP request: system presto is looking for the Ethernet address of wait. It would appear that wait is currently not responding, since there is no reply.
• Line 2 is not an IP message at all. tcpdump shows the Ethernet addresses and the beginning of the packet. We don't consider this kind of request in this book.
• Line 3 is a broadcast ntp message. We looked at ntp on page 155.
• Line 4 is another attempt by presto to find the IP address of wait.
• Line 5 is a broadcast message from bumble on the rwho port, giving information about its current load averages and how long it has been up. See the man page rwho(1) for more information.
• Line 6 is from a TCP connection between port 6000 on freebie and port 1089 on presto. It is sending 384 bytes (with the sequence numbers 536925467 to 536925851; see page 282), and is acknowledging that the last byte it received from presto had the sequence number 325114346. The window size is 17280.
• Line 7 is another ARP request. presto is looking for the Ethernet address of freebie. How can that happen? We've just seen that they have a TCP connection. In fact, ARP information expires after 20 minutes. It's quite possible that all connections between presto and freebie have been dormant for this period, so presto needs to find freebie's IP address again.
• Line 8 is the ARP reply from freebie to presto giving its Ethernet address.
• Line 9 shows a reply from presto on the connection to freebie that we saw online 6. It acknowledges the data up to sequence number 536925851, but doesn't send any itself.
• Line 10 shows another 448 bytes of data from freebie to presto, and acknowledges the same sequence number from presto as in line 6.

Packet loss revisited

Getting back to our packet loss problem, the following example shows the result of communicating on a less-than-perfect ssh connection to http://hub.FreeBSD.org, specifically between port 1019 on freebie and port 22, the ssh port, on hub. To make things more readable, the names have been truncated to freebie and hub. In real-life output, they would be reported as http://freebie.example.org and http://hub.FreeBSD.org. In addition, tcpdump reports a tos (type of service) field, which has also been removed. It doesn't interest us here.

# tcpdump -i ppp0 host hub.freebsd.org
14:16:35.990506  freebie.1019 > hub.22:  P  20:40(20) ack 77 win 17520 (DF)
14:16:36.552149  hub.22 > freebie.1019:  P  77:97(20) ack 40 win 17520 (DF)
14:16:36.722290  freebie.1019 > hub.22:  .  ack 97 win 17520 (DF)
14:16:39.344229  freebie.1019 > hub.22:  P  40:60(20) ack 97 win 17520 (DF)
14:16:41.321850  freebie.1019 > hub.22:  P  40:60(20) ack 97 win 17520 (DF)

The first line shows freebie sending bytes 20 to 40 of the stream to hub, and also acknowledging receipt of everything up to byte 77 of the stream from hub. On the next line, hub sends bytes 77 to 97 and acknowledges receiving up to byte 40 of the stream from freebie. freebie then sends another 20 bytes and acknowledges what it has received from hub.

After two seconds, freebie has not received an acknowledgment from hub that its data has been received, so on the last line it sends the packet again.

14:16:42.316150 hub.22 > freebie.1019: P 97:117(20) ack 60 win 17520 (DF) 
14:16:42.321773 freebie.1019 > hub.22:  . ack 117 win 17520 (DF)

This is the missing acknowledgment—t came another second later, along with some more data. freebie acknowledges receiving it, but doesn't send anymore data.

14:16:47.428694 freebie.1019 > hub.22:  P 60:80(20) ack 117 win 17520 (DF)
14:16:48.590805 freebie.1019 > hub.22:  P 80:100(20) ack 117 win 17520 (DF)
14:16:49.055735 freebie.1019 > hub.22:  P 100:120(20) ack 117 win 17520 (DF)
14:16:49.190703 hub.22 > freebie.1019:  P 137:157(20) ack 100 win 17520 (DF)

Five seconds later, freebie sends more data, up to byte 120 to hub. hub replies with its own data an acknowledgment up to byte 100. Unfortunately, the data it sent (bytes 137 to 157) don't line up with the last previously received data (byte 117 at 14:16:42.316150): bytes 117 to 137 are missing. freebie thus repeats the previous acknowledgment and then continues sending its data:

14:16:49.190890 freebie.1019 > hub.22:  . ack 117 win 17520 (DF)
14:16:49.538607 freebie.1019 > hub.22: P 120:140(20) ack 117 win 17520 (DF)
14:16:49.599395 hub.22 > freebie.1019: P 157:177(20) ack 120 win 17520 (DF)

Here, hub has sent yet more data, now acknowledging the data that freebie sent at 14:16:49.055735. It still hasn't sent the data in the byte range 117 to 136, so freebie resends the last acknowledgment again and continues sending data:

14:16:49.599538 freebie.1019 > hub.22:  . ack 117 win 17520 (DF)
14:16:49.620506 freebie.1019 > hub.22: P 140:160(20) ack 117 win 17520 (DF)
14:16:50.066698 hub.22 > freebie.1019: P 177:197(20) ack 140 win 17520 (DF)

Again hub has sent more data, still without sending the missing packet. freebie tries yet again, and then continues sending data:

14:16:50.066868 freebie.1019 > hub.22:  . ack 117 win 17520 (DF)
14:16:51.820708 freebie.1019 > hub.22:  P 140:160(20) ack 117 win 17520 (DF)
14:16:52.308992 hub.22 > freebie.1019:  . ack 160 win 17520 (DF)
14:16:55.251176 hub.22 > freebie.1019:  P 117:217(100) ack 160 win 17520 (DF)

Finally, hub resends the missing data, with bytes from 117 to 217. freebie is now happy, and acknowledges receipt of all the data up to 217. That's all we transmitted, so after about 1.5 seconds the two systems exchange final acknowledgments:

14:16:55.251358 freebie.1019 > hub.22: .
14:16:56.690779 hub.login > freebie.1015:
14:16:56.690941 freebie.1015 > hub.login:
ack 217 win 17420 (DF) . ack 3255467530 win 17520 . ack 1 win 17520 (DF)

This connection is less than perfect. Why? You can use traceroute to find out where it's happening, but unless the place is within your ISP's network, you can't do much about it.

Transport and application layers

If you have got this far, the chances are that things will now work. Problems in transport layer are rare. About the only things that can still cause problems are the individual applications. We'll look at some of these in the relevant chapters.

One particular problem is the Domain Name Service. This is such an integral part of the Internet Protocols that people tend to forget that it's really an application. If you get a timeout accessing a web URL, for example, there's a good chance that DNS is causing the problem. Take a look at Chapter 21, The Domain Name Service, for some ideas.

Ethereal

tcpdump is a powerful tool, but the examples above show that the output isn't the easiest thing in the world to read. An alternative is ethereal, a program in the Ports Collection (/usr/ports/net/ethereal) that displays the data in much more detail, as Figure 23-1 shows.

The screen is divided into three windows:

• The top part shows individual packets (numbered 51 to 54 in this example). The line in inverse video has been selected for display in more detail.
• The middle window shows the full packet. By clicking with the mouse on the boxes on the left, you can expand or reduce the amount of information being displayed.
• The bottom window shows the raw data as hexadecimal and ASCII.

In practice, you'd probably want to scale the window much larger than in this example.

This image shows part of the password for a telnet login session being returned. It illustrates one of the reasons you should never use telnet to connect across the Internet.

Рис. 23.1. ethereal display