Hi all,
If this looks familiar, read on...
PING 64.53.54.1 (64.53.54.1): 56 octets data
64 octets from 64.53.54.1: icmp_seq=0 ttl=253 time=4452.8 ms
wrong data byte #0 should be 0x3b but was 0x3737 da b0 3a 88 9e e 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
See bug summary at bottom if you don't want to wade through all the gory
details.
Pierre
=================== RACE BUG in PING =================
I was having what appeared to be network problems and was, to say the least,
SHOCKED to see the above ping putput...
The thought of hardware going bad did not sit well... so, here's how I
discovered that "ping" has a race bug...
My topology, which helped in isolating this bug is this:
+---------------(10)-------+ <--- for sniffing only
| |
| | [fork]
| +---+ | +---+
eth1 | L | +---+ | R |
[bones]--(100)--| i | | | | o |
| n | | H | | u |
[woody]--(100)--| k |--(10)--| u |--(10)--| t |--(10)--DSL--Z--64.53.54.1
| S | | b | | e |
[homer]--(10)---| y | | | | r |
| s | +---+ +---+
+---+
The bug was triggered by a fully maxed out DSL link (rsync).
Here is the initial ping...
[root@bones pfortin]# ping 64.53.54.1
PING 64.53.54.1 (64.53.54.1): 56 octets data
64 octets from 64.53.54.1: icmp_seq=0 ttl=253 time=4452.8 ms
wrong data byte #0 should be 0x3b but was 0x3737 da b0 3a 88 9e e 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
64 octets from 64.53.54.1: icmp_seq=1 ttl=253 time=4432.8 ms
wrong data byte #0 should be 0x3c but was 0x3838 da b0 3a 43 91 e 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
64 octets from 64.53.54.1: icmp_seq=2 ttl=253 time=4536.3 ms
wrong data byte #0 should be 0x3d but was 0x3939 da b0 3a f3 91 e 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
64 octets from 64.53.54.1: icmp_seq=3 ttl=253 time=4304.1 ms
wrong data byte #0 should be 0x3e but was 0x3a3a da b0 3a 9f 92 e 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
--- 64.53.54.1 ping statistics ---
8 packets transmitted, 4 packets received, 50% packet loss
round-trip min/avg/max = 4304.1/4431.5/4536.3 ms
For more proof (note random starting "data byte #0" contents), let's get the
output from a couple more pings to see the bug more clearly later... ("wrong
data byte #0 should be <foo> but was <bar>")
[root@bones pfortin]# ping 64.53.54.1
PING 64.53.54.1 (64.53.54.1): 56 octets data
64 octets from 64.53.54.1: icmp_seq=0 ttl=253 time=4312.4 ms
wrong data byte #0 should be 0xbe but was 0xbaba de b0 3a b 10 f 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
64 octets from 64.53.54.1: icmp_seq=1 ttl=253 time=4343.3 ms
wrong data byte #0 should be 0xbf but was 0xbbbb de b0 3a 18 f0 e 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
64 octets from 64.53.54.1: icmp_seq=2 ttl=253 time=4574.1 ms
wrong data byte #0 should be 0xc0 but was 0xbcbc de b0 3a ac ef e 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
--- 64.53.54.1 ping statistics ---
8 packets transmitted, 3 packets received, 62% packet loss
round-trip min/avg/max = 4312.4/4409.9/4574.1 ms
[root@bones pfortin]# ping 64.53.54.1
PING 64.53.54.1 (64.53.54.1): 56 octets data
64 octets from 64.53.54.1: icmp_seq=0 ttl=253 time=3893.4 ms
wrong data byte #0 should be 0xe0 but was 0xdddd de b0 3a 7f 3b 0 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
64 octets from 64.53.54.1: icmp_seq=1 ttl=253 time=3887.8 ms
wrong data byte #0 should be 0xe1 but was 0xdede de b0 3a d7 31 0 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
64 octets from 64.53.54.1: icmp_seq=2 ttl=253 time=4142.4 ms
wrong data byte #0 should be 0xe3 but was 0xdfdf de b0 3a 0 31 0 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
64 octets from 64.53.54.1: icmp_seq=3 ttl=253 time=4474.4 ms
wrong data byte #0 should be 0xe4 but was 0xe0e0 de b0 3a 4d 30 0 0
8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22
23 24 25 26 27
28 29 2a 2b 2c 2d 2e 2f
--- 64.53.54.1 ping statistics ---
8 packets transmitted, 4 packets received, 50% packet loss
round-trip min/avg/max = 3887.8/4099.5/4474.4 ms
So... IF this is a hardware problem, then we SHOULD see the same output if we
tell ping to wait longer; BUT... waiting 5 seconds for the replies:
[root@bones pfortin]# ping -i 5 64.53.54.1
PING 64.53.54.1 (64.53.54.1): 56 octets data
64 octets from 64.53.54.1: icmp_seq=0 ttl=253 time=3989.7 ms
64 octets from 64.53.54.1: icmp_seq=1 ttl=253 time=3881.6 ms
64 octets from 64.53.54.1: icmp_seq=2 ttl=253 time=4014.4 ms
64 octets from 64.53.54.1: icmp_seq=3 ttl=253 time=4594.2 ms
64 octets from 64.53.54.1: icmp_seq=4 ttl=253 time=4316.2 ms
64 octets from 64.53.54.1: icmp_seq=5 ttl=253 time=3512.1 ms
64 octets from 64.53.54.1: icmp_seq=6 ttl=253 time=4423.4 ms
64 octets from 64.53.54.1: icmp_seq=7 ttl=253 time=4550.2 ms
--- 64.53.54.1 ping statistics ---
9 packets transmitted, 8 packets received, 11% packet loss
round-trip min/avg/max = 3512.1/4160.2/4594.2 ms
Wellllll.... these pings are just fine!!
EXCEPT for the long echo delays as witnessed by "time="!
OK... why my topology helped: Using ethereal, the packets were sniffed via
eth1 and they were OK! Note that ethereal just reports what it sees; it does
not care how long it takes for the replies to return.
Now, let's move to the router... (Cisco)
fork#ping 64.53.54.1
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 64.53.54.1, timeout is 2 seconds:
.....
Success rate is 0 percent (0/5)
Hmmm... certainly looks like there may be a problem...
Let's turn on debugging...
fork#debug ip icmp
ICMP packet debugging is on
fork#ping 64.53.54.1
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 64.53.54.1, timeout is 2 seconds:
..
Mar 15 10:44:17: ICMP: echo reply rcvd, src 64.53.54.1, dst 64.53.54.146.
Mar 15 10:44:19: ICMP: echo reply rcvd, src 64.53.54.1, dst 64.53.54.146.
Mar 15 10:44:21: ICMP: echo reply rcvd, src 64.53.54.1, dst 64.53.54.146.
Success rate is 0 percent (0/5)
fork#
Mar 15 10:44:23: ICMP: echo reply rcvd, src 64.53.54.1, dst 64.53.54.146
Mar 15 10:44:26: ICMP: echo reply rcvd, src 64.53.54.1, dst 64.53.54.146
Note that while all pings "failed"**, all 5 replies DID make it back.
** two "." and the remaining three "." are at the ends of the first three debug
outputs.
Note that the router does not complain that the ICMP replies are bad; it just
flags them as missing because they did not return before the timer expired.
Just as in the Linux ping, let's see what happens when the Cisco router is told
to wait longer for the replies...
fork#ping
Protocol [ip]:
Target IP address: 64.53.54.1
Repeat count [5]:
Datagram size [100]:
Timeout in seconds [2]: 5
Extended commands [n]:
Sweep range of sizes [n]:
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 64.53.54.1, timeout is 5 seconds:
!!!!!
Success rate is 100 percent (5/5), round-trip min/avg/max = 3828/4116/4464 ms
Looks good...
BUG SUMMARY:
------------
Linux's "ping" waits (default= 1 sec) for a reply and proceeds to the next ping
after INCREMENTING "data byte #0". If a reply is seen before the timeout, or
not at all, then ping does the right thing.
If a reply is delayed and the timer expires, ping increments "data byte #0" for
the next packet to send. Again, no problem here per se... HOWEVER... ping
fails to take into account the possibility of delayed replies. When such a
reply finally shows up, ping compares "data byte #0" to the UPDATED value. No
need to maintain a list of sent counters; a simple algorithm works...
Ping SHOULD compare "data byte #0" after first adjusting for the delay this way:
- save starting"data byte #0"
- when reply arrives:
if "data byte #0" == starting"data byte #0" + icmp_seq:
OK ^^^^^^^^^^
else: error()
Any fix should also take into account "wrapping" of the random "data byte #0"
counter.
Also, the output:
wrong data byte #0 should be 0x3b but was 0x3737 da b0 3a 88 9e e 0
probably should be reformatted to read:
wrong data byte #0 should be 0x3b but was 0x37 37 da b0 3a 88 9e e 0
Note that this false-problem output also confirms the bug:
expecting: 0x3b
got: 0x37
proper check: 0x37 + ("time=4452.8 ms" * wait_timer)
= 0x37 + (int(4.4528) * 1) # seconds
= 0x37 + (4 * 1)
= 0x3b # Gee....!
By fixing this bug, we'll be able to eliminate the "I'm getting this..." and the
"you have a hardware problem" emails, and the resulting wasted time and $$
trying to fix hardware which is really OK...
--
Linux (Up 27 days) -- Reboots are for system upgrades... not Windows X^P
Last reboot reason: 02/14/01: testing startup changes for DSL
