Bug 404761

Summary: Packet lost inside kernel
Product: [Fedora] Fedora Reporter: Eric Hopper <eric-bugs>
Component: kernelAssignee: Kernel Maintainer List <kernel-maint>
Status: CLOSED NOTABUG QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: low    
Version: 7   
Target Milestone: ---   
Target Release: ---   
Hardware: athlon   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2007-12-02 02:00:45 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Eric Hopper 2007-11-29 17:59:39 UTC
My Fedora based router is dropping a packet in between the time I can see it
with tcpdump and the time it hits the raw:PREROUTING table.

In the following, notice how the debug2 LOG target never seems to be fired.

Showing the table:
# iptables -t raw -nL PREROUTING Chain PREROUTING (policy ACCEPT)
target     prot opt source               destination         
LOG        icmp --  0.0.0.0/0            216.254.16.18       LOG flags 0 level 4
prefix `debug ' 
LOG        icmp --  0.0.0.0/0            216.254.16.17       LOG flags 0 level 4
prefix `debug2 ' 

------

What tcpdump shows:

# tcpdump -eni eth0 ip host 209.40.196.143 and not tcp
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:48:05.949100 00:90:1a:40:a2:a2 > 00:e0:81:2c:b6:e2, ethertype IPv4 (0x0800),
length 98: 209.40.196.143 > 216.254.16.18: ICMP echo request, id 37964, seq 1,
length 64
09:48:07.948419 00:90:1a:40:a2:a2 > 00:e0:81:2c:b6:e2, ethertype IPv4 (0x0800),
length 98: 209.40.196.143 > 216.254.16.18: ICMP echo request, id 37964, seq 2,
length 64
09:48:09.947579 00:90:1a:40:a2:a2 > 00:e0:81:2c:b6:e2, ethertype IPv4 (0x0800),
length 98: 209.40.196.143 > 216.254.16.18: ICMP echo request, id 37964, seq 3,
length 64
09:48:12.863715 00:90:1a:40:a2:a2 > 00:0d:61:91:5d:e6, ethertype IPv4 (0x0800),
length 98: 209.40.196.143 > 216.254.16.17: ICMP echo request, id 49484, seq 1,
length 64
09:48:12.863960 00:0d:61:91:5d:e6 > 00:90:1a:40:a2:a2, ethertype IPv4 (0x0800),
length 98: 216.254.16.17 > 209.40.196.143: ICMP echo reply, id 49484, seq 1,
length 64
09:48:14.864049 00:90:1a:40:a2:a2 > 00:0d:61:91:5d:e6, ethertype IPv4 (0x0800),
length 98: 209.40.196.143 > 216.254.16.17: ICMP echo request, id 49484, seq 2,
length 64
09:48:14.864258 00:0d:61:91:5d:e6 > 00:90:1a:40:a2:a2, ethertype IPv4 (0x0800),
length 98: 216.254.16.17 > 209.40.196.143: ICMP echo reply, id 49484, seq 2,
length 64
09:48:16.863956 00:90:1a:40:a2:a2 > 00:0d:61:91:5d:e6, ethertype IPv4 (0x0800),
length 98: 209.40.196.143 > 216.254.16.17: ICMP echo request, id 49484, seq 3,
length 64
09:48:16.864159 00:0d:61:91:5d:e6 > 00:90:1a:40:a2:a2, ethertype IPv4 (0x0800),
length 98: 216.254.16.17 > 209.40.196.143: ICMP echo reply, id 49484, seq 3,
length 64

------

What /var/log/messages shows:

Nov 29 09:48:12 dark kernel: debug2 IN=eth0 OUT=
MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=209.40.196.143
DST=216.254.16.17 LEN=84 TOS=0x00 PREC=0x20 TTL=58 ID=0 DF PROTO=ICMP TYPE=8
CODE=0 ID=49484 SEQ=1 
Nov 29 09:48:14 dark kernel: debug2 IN=eth0 OUT=
MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=209.40.196.143
DST=216.254.16.17 LEN=84 TOS=0x00 PREC=0x20 TTL=58 ID=0 DF PROTO=ICMP TYPE=8
CODE=0 ID=49484 SEQ=2 
Nov 29 09:48:16 dark kernel: debug2 IN=eth0 OUT=
MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=209.40.196.143
DST=216.254.16.17 LEN=84 TOS=0x00 PREC=0x20 TTL=58 ID=0 DF PROTO=ICMP TYPE=8
CODE=0 ID=49484 SEQ=3 
Nov 29 09:50:31 dark kernel: debug2 IN=eth0 OUT=
MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=67.15.240.43 DST=216.254.16.17
LEN=78 TOS=0x00 PREC=0x20 TTL=53 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=1 SEQ=9131

Comment 1 Eric Hopper 2007-11-29 18:03:05 UTC
Better kernel log:

Nov 29 09:47:58 dark kernel: device eth0 entered promiscuous mode
Nov 29 09:47:58 dark kernel: audit(1196358478.738:10): dev=eth0 prom=256
old_prom=0 auid=4294967295
Nov 29 09:48:12 dark kernel: debug2 IN=eth0 OUT=
MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=209.40.196.143
DST=216.254.16.17 LEN=84 TOS=0x00 PREC=0x20 TTL=58 ID=0 DF PROTO=ICMP TYPE=8
CODE=0 ID=49484 SEQ=1 
Nov 29 09:48:14 dark kernel: debug2 IN=eth0 OUT=
MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=209.40.196.143
DST=216.254.16.17 LEN=84 TOS=0x00 PREC=0x20 TTL=58 ID=0 DF PROTO=ICMP TYPE=8
CODE=0 ID=49484 SEQ=2 
Nov 29 09:48:16 dark kernel: debug2 IN=eth0 OUT=
MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=209.40.196.143
DST=216.254.16.17 LEN=84 TOS=0x00 PREC=0x20 TTL=58 ID=0 DF PROTO=ICMP TYPE=8
CODE=0 ID=49484 SEQ=3 
Nov 29 09:50:31 dark kernel: debug2 IN=eth0 OUT=
MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=67.15.240.43 DST=216.254.16.17
LEN=78 TOS=0x00 PREC=0x20 TTL=53 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=1 SEQ=9131 


Comment 2 Chuck Ebbert 2007-11-29 18:25:32 UTC
(In reply to comment #0)
> 
> In the following, notice how the debug2 LOG target never seems to be fired.
> 
> LOG        icmp --  0.0.0.0/0            216.254.16.17       LOG flags 0 level 4
> prefix `debug2 ' 

> Nov 29 09:48:12 dark kernel: debug2 IN=eth0 OUT=
                               ^^^^^^
debug2 is there-------------------

> MAC=00:0d:61:91:5d:e6:00:90:1a:40:a2:a2:08:00 SRC=209.40.196.143
> DST=216.254.16.17 LEN=84 TOS=0x00 PREC=0x20 TTL=58 ID=0 DF PROTO=ICMP TYPE=8
> CODE=0 ID=49484 SEQ=1 


Comment 3 Eric Hopper 2007-11-29 18:36:13 UTC
I'm sorry, I meant 'debug'.  'debug2' is associated with the rule for
216.254.16.17, an IP that is properly routed and everything.  And 'debug' is
associated with the rule for 216.254.16.18, an IP for which all of the incoming
packets are currently being eaten by the kernel somewhere between tcpdump and
raw:PREROUTING

Comment 4 Chuck Ebbert 2007-11-29 19:06:14 UTC
Please post the output of the 'ifconfig' command.

Comment 5 Eric Hopper 2007-11-29 19:13:17 UTC
eth0      Link encap:Ethernet  HWaddr 00:0D:61:91:5D:E6  
          inet addr:216.254.16.16  Bcast:216.254.16.16  Mask:255.255.255.255
          inet6 addr: fe80::20d:61ff:fe91:5de6/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:321895 errors:0 dropped:0 overruns:0 frame:0
          TX packets:270299 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:173078587 (165.0 MiB)  TX bytes:150066298 (143.1 MiB)
          Interrupt:22 Base address:0xa000

Comment 6 Chuck Ebbert 2007-11-30 20:34:49 UTC
The packets destined for 216.254.16.18 are being sent to a different network
adapter, with MAC address 00:e0:81:2c:b6:e2

Comment 7 Eric Hopper 2007-12-02 02:00:45 UTC
Oh, you're right.  I didn't notice this.  How interesting and odd.  Thanks a
whole lot.  This is now not the bug I thought it was, but may still be a bug.

216.254.16.16 is a firewall.  I have 4 static IPs not in a subnetwork.  I have
eth0 configured to proxy arp.  So 216.254.16.1 (the gateway at the ISP) should
never have seen that ethernet address, which is the Ethernet address of
216.254.16.18.

Oh!  I know how that happened.  It was because of a debugging session with my
ISP.  It took many minutes awhile for the gateway's ARP cache to timeout. 
Something very weird is going on with the way my ISP is routing packets and
they've been trying to blame it on me.

Sorry to call in a bug report when it wasn't.