Every other char with LOG netfilter output (bug?)

Every other char with LOG netfilter output (bug?)

[Dâniel Fraga]

	Since Linux kernel 2.6.25, I get stalled connections and when it happens, I have this on the log:

Oct 28 13:39:22 tux vmunix: 1:3e:79:01:fe:b2:80 R=9.6.. S=9.6.. E=9
O=x0PE=x0TL6 D410POOUPST10 P=41 E=7

	It seems that are missing chars here.

	A bug?

	Ps: in fact this issue seems to be much more complex than this. There's a huge thread we 
talked about those stalled connections, but we are unable to discover what causes this, so I opened 
this bug report:

http://bugzilla.kernel.org/show_bug.cgi?id=11588

	At least if netfilter developers could figure it out why the above log line happens, maybe we 
could trace this bug and solve it.

	Thank you!

	Ps: I tested with 2.6.28-rc2 and the problem remains.

-- 
Linux 2.6.28-rc2: Killer Bat of Doom
http://u-br.net

Re: Every other char with LOG netfilter output (bug?)

[Patrick McHardy]

Dâniel Fraga wrote:
> 	Since Linux kernel 2.6.25, I get stalled connections and when it happens, I have this on the log:
> 
> Oct 28 13:39:22 tux vmunix: 1:3e:79:01:fe:b2:80 R=9.6.. S=9.6.. E=9
> O=x0PE=x0TL6 D410POOUPST10 P=41 E=7
> 
> 	It seems that are missing chars here.
> 
> 	A bug?

Seems likely. Is that an SMP machine? Its possible that the ringbuffer
simply overflows before the logging daemon gets a chance to capture it,
but that should only cause truncated lines.

What do your logging rules that might be responsible for this look like?

> 	Ps: in fact this issue seems to be much more complex than this. There's a huge thread we 
> talked about those stalled connections, but we are unable to discover what causes this, so I opened 
> this bug report:
> 
> http://bugzilla.kernel.org/show_bug.cgi?id=11588
> 
> 	At least if netfilter developers could figure it out why the above log line happens, maybe we 
> could trace this bug and solve it.

I can't see anything in that report that would ring a bell.
Are you using any of the more unusual networking features,
like QoS, policy routing etc?

--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Every other char with LOG netfilter output (bug?)

[Dâniel Fraga]

On Tue, 28 Oct 2008 18:40:17 +0100
Patrick McHardy <kaber@trash.net> wrote:

> Seems likely. Is that an SMP machine? Its possible that the ringbuffer
> simply overflows before the logging daemon gets a chance to capture it,
> but that should only cause truncated lines.

	Yes, SMP (Athlon64 X2 and I noticed it on a Xeon 3040 too).

> What do your logging rules that might be responsible for this look like?

	My rules are pretty simple:

# Generated by iptables-save v1.4.2 on Tue Oct 28 15:49:09 2008
*filter
:INPUT DROP [0:0]
:FORWARD DROP [0:0]
:OUTPUT ACCEPT [454613:1227743602]
:FLDR - [0:0]
:LDR - [0:0]
-A INPUT -i lo -j ACCEPT 
-A INPUT -m state --state RELATED,ESTABLISHED -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 21 -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 113 -j REJECT --reject-with tcp-reset 
-A INPUT -s 192.168.1.0/24 -p tcp -m tcp --dport 137:139 -j ACCEPT 
-A INPUT -s 192.168.1.0/24 -p udp -m udp --dport 137:138 -j ACCEPT 
-A INPUT -p udp -m udp --dport 123 -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 1863 -m comment --comment "AMSN" -j ACCEPT 
-A INPUT -p udp -m udp --dport 1194:1195 -m comment --comment "OpenVPN" -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 6346 -m comment --comment "gnutella" -j ACCEPT 
-A INPUT -p udp -m udp --dport 6346 -m comment --comment "gnutella" -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 6881:6899 -m comment --comment "AMSN" -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 5190:5199 -m comment --comment "ICQ" -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 8010 -m comment --comment "Jabber" -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 23399 -m comment --comment "Skype" -j ACCEPT 
-A INPUT -p tcp -m tcp --dport 51526 -m comment --comment "Azureus" -j ACCEPT 
-A INPUT -p icmp -j ACCEPT 
-A INPUT -p udp -m udp --sport 5001 --dport 5001 -j ACCEPT 
-A INPUT -j LDR 
-A FORWARD -s 192.168.1.0/24 -m state --state NEW -j ACCEPT 
-A FORWARD -m state --state RELATED,ESTABLISHED -j ACCEPT 
-A FORWARD -j FLDR 
-A FLDR -j LOG --log-prefix "DROP FORWARD: " --log-level 6 
-A FLDR -j DROP 
-A LDR -j LOG --log-prefix "DROP INPUT: " --log-level 6 
-A LDR -j DROP 
COMMIT
# Completed on Tue Oct 28 15:49:09 2008

> I can't see anything in that report that would ring a bell.
> Are you using any of the more unusual networking features,
> like QoS, policy routing etc?

	No. Nothing special.

	The interesting is that this behaviour started at 2.6.25 kernel version, but
I couldn't find anything that was changed between .24 and .25 to cause this. Very strange.

	Is there a way I can trace the function that generates the log output syslog line?
I use Function Tracer included in 2.6.27 kernel already, but I need a way to stop the tracing
it exactly at the point when this happens, otherwise the tracing buffer will be replaced...

-- 

Re: Every other char with LOG netfilter output (bug?)

[Patrick McHardy]

Dâniel Fraga wrote:
> On Tue, 28 Oct 2008 18:40:17 +0100
> Patrick McHardy <kaber@trash.net> wrote:
> 
>> Seems likely. Is that an SMP machine? Its possible that the ringbuffer
>> simply overflows before the logging daemon gets a chance to capture it,
>> but that should only cause truncated lines.
> 
> 	Yes, SMP (Athlon64 X2 and I noticed it on a Xeon 3040 too).
> 
>> What do your logging rules that might be responsible for this look like?
> 
> 	My rules are pretty simple:
> 
> # Generated by iptables-save v1.4.2 on Tue Oct 28 15:49:09 2008
> *filter
> :INPUT DROP [0:0]
> :FORWARD DROP [0:0]
> :OUTPUT ACCEPT [454613:1227743602]
> :FLDR - [0:0]
> :LDR - [0:0]
> ...
> -A FLDR -j LOG --log-prefix "DROP FORWARD: " --log-level 6 
> -A FLDR -j DROP 
> -A LDR -j LOG --log-prefix "DROP INPUT: " --log-level 6 
> -A LDR -j DROP 
> COMMIT
> # Completed on Tue Oct 28 15:49:09 2008
> 
> 	The interesting is that this behaviour started at 2.6.25 kernel version, but
> I couldn't find anything that was changed between .24 and .25 to cause this. Very strange.

I have no idea why the log output is corrupted like this, but
some things you could try:

- use serial console, which should at least avoid any corruption
   triggered by ringbuffer overflows. It many packets are logged
   it will slow down your system considerably though.

- use ULOG or nfnetlink_log: this allows to capture a full copy
   of the packet in userspace, which might be helpful for further
   analysis.

> 	Is there a way I can trace the function that generates the log output syslog line?
> I use Function Tracer included in 2.6.27 kernel already, but I need a way to stop the tracing
> it exactly at the point when this happens, otherwise the tracing buffer will be replaced...

I'm not familiar with ftrace, but you could manually instrument it
(net/ipv4/netfilter/ipt_LOG.c). I'd try nfnetlink_log first though.

--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Every other char with LOG netfilter output (bug?)

[Jan Engelhardt]

On Tuesday 2008-10-28 14:13, Patrick McHardy wrote:
>> 
>> 	The interesting is that this behaviour started at 2.6.25 kernel
>> version, but
>> I couldn't find anything that was changed between .24 and .25 to cause this.
>> Very strange.
>
> I have no idea why the log output is corrupted like this, but
> some things you could try:
>
> - use serial console, which should at least avoid any corruption
>  triggered by ringbuffer overflows. It many packets are logged
>  it will slow down your system considerably though.

JFYI, if it was a ring issue, the start of the string would be
overwritten, and not just random chars.

Re: Every other char with LOG netfilter output (bug?)

[Patrick McHardy]

Jan Engelhardt wrote:
> On Tuesday 2008-10-28 14:13, Patrick McHardy wrote:
>>> 	The interesting is that this behaviour started at 2.6.25 kernel
>>> version, but
>>> I couldn't find anything that was changed between .24 and .25 to cause this.
>>> Very strange.
>> I have no idea why the log output is corrupted like this, but
>> some things you could try:
>>
>> - use serial console, which should at least avoid any corruption
>>  triggered by ringbuffer overflows. It many packets are logged
>>  it will slow down your system considerably though.
> 
> JFYI, if it was a ring issue, the start of the string would be
> overwritten, and not just random chars.

I know, but judging by the few things that look like valid
LOG fragments, there seems to be more corruption than just
the ring buffer going on, so it might be worth a try.
I'd try nfnetlink_log first though.

Re: Every other char with LOG netfilter output (bug?)

[Dâniel Fraga]

On Tue, 28 Oct 2008 19:13:33 +0100
Patrick McHardy <kaber@trash.net> wrote:

> (net/ipv4/netfilter/ipt_LOG.c). I'd try nfnetlink_log first though.

	Ok, I'll try nfnetlink_log as you suggested and as soon as I
have something relevant I return. Thank you very much!


-- 

Re: Every other char with LOG netfilter output (bug?)

[Dâniel Fraga]

On Tue, 28 Oct 2008 19:13:33 +0100
Patrick McHardy <kaber@trash.net> wrote:

> I'm not familiar with ftrace, but you could manually instrument it
> (net/ipv4/netfilter/ipt_LOG.c). I'd try nfnetlink_log first though.

	Hi Patrick, I installed ulogd2 with all necessary stuff. The
normal log is working (with the default ulogd.conf), but how can I
configure it to log the full packets? If you can provide me a sample
configuration, I'll appreciate!

	Thank you!


-- 

Re: Every other char with LOG netfilter output (bug?)

[Patrick McHardy]

Dâniel Fraga wrote:
> On Tue, 28 Oct 2008 19:13:33 +0100
> Patrick McHardy <kaber@trash.net> wrote:
> 
>> I'm not familiar with ftrace, but you could manually instrument it
>> (net/ipv4/netfilter/ipt_LOG.c). I'd try nfnetlink_log first though.
> 
> 	Hi Patrick, I installed ulogd2 with all necessary stuff. The
> normal log is working (with the default ulogd.conf), but how can I
> configure it to log the full packets? If you can provide me a sample
> configuration, I'll appreciate!

One thing you need is to specify the amount of bytes you want transfered
to userspace:

iptables ... -j NFLOG --nflog-range 65535

The printpkt output plugin doesn't log the full packet, but I'm not
sure how to configure the pcap plugin (or whether it works at all
in ulogd2, which is still somewhere between alpha and beta).
Pablo (CCed) might be able to help.

--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Every other char with LOG netfilter output (bug?)

[Pablo Neira Ayuso]

Patrick McHardy wrote:
> Dâniel Fraga wrote:
>> On Tue, 28 Oct 2008 19:13:33 +0100
>> Patrick McHardy <kaber@trash.net> wrote:
>>
>>> I'm not familiar with ftrace, but you could manually instrument it
>>> (net/ipv4/netfilter/ipt_LOG.c). I'd try nfnetlink_log first though.
>>
>>     Hi Patrick, I installed ulogd2 with all necessary stuff. The
>> normal log is working (with the default ulogd.conf), but how can I
>> configure it to log the full packets? If you can provide me a sample
>> configuration, I'll appreciate!
> 
> One thing you need is to specify the amount of bytes you want transfered
> to userspace:
> 
> iptables ... -j NFLOG --nflog-range 65535
> 
> The printpkt output plugin doesn't log the full packet, but I'm not
> sure how to configure the pcap plugin (or whether it works at all
> in ulogd2, which is still somewhere between alpha and beta).
> Pablo (CCed) might be able to help.

The plugin works fine here. Uncomment the following lines:

# plugin="/usr/lib/ulogd/ulogd_output_PCAP.so

# this is a stack for NFLOG packet-based logging to PCAP
# stack=log1:NFLOG,base1:BASE,pcap1:PCAP

And make sure you have the appropriate section:

[pcap1]
file="/var/log/ulogd.pcap"
sync=1

-- 
"Los honestos son inadaptados sociales" -- Les Luthiers
--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Every other char with LOG netfilter output (bug?)

[Dâniel Fraga]

[-- Attachment #1: Type: text/plain, Size: 1138 bytes --]

On Thu, 30 Oct 2008 08:15:14 +0100
Patrick McHardy <kaber@trash.net> wrote:

> One thing you need is to specify the amount of bytes you want transfered
> to userspace:
> 
> iptables ... -j NFLOG --nflog-range 65535

	Ok, I forgot to use --nflog-range, but I have an issue. I'm
sending anyway... maybe there's some hint of what is happening:

	1) for comparison, on old LOG target I get:

Oct 30 20:55:16 tux vmunix: 6 P=7LN38

	2) on NFLOG, using syslog emul, I get:

Oct 30 20:55:16 tux DROP INPUT:  IN=eth0 OUT= MAC=ff:ff:ff:ff:ff:ff:00:21:00:31:6c:f0:08:00 SRC=192.168.1.100 DST=255.255.255.255 LEN=328 TOS=00 PREC=0x00 TTL=128 ID=21248 PROTO=UDP SPT=68 DPT=67 LEN=308 MARK=0 

Oct 30 20:55:19 tux DROP INPUT:  IN=eth0 OUT= MAC=ff:ff:ff:ff:ff:ff:00:21:00:31:6c:f0:08:00 SRC=192.168.1.100 DST=255.255.255.255 LEN=328 TOS=00 PREC=0x00 TTL=128 ID=21250 PROTO=UDP SPT=68 DPT=67 LEN=308 MARK=0

	You can compare both and see what's missing on the first one (LOG).

	And I attached the pcap log binary file (bzipped). If it's
uselles, wait that I'll send a new one with -nflog-range 65535, which I
forgot to use.

	Thank you very much!

-- 

[-- Attachment #2: ulogd.pcap.bz2 --]
[-- Type: application/octet-stream, Size: 636 bytes --]

Re: Every other char with LOG netfilter output (bug?)

[Dâniel Fraga]

[-- Attachment #1: Type: text/plain, Size: 1729 bytes --]

On Thu, 30 Oct 2008 08:15:14 +0100
Patrick McHardy <kaber@trash.net> wrote:

> One thing you need is to specify the amount of bytes you want transfered
> to userspace:
> 
> iptables ... -j NFLOG --nflog-range 65535

	Another one (now with --nflog-range 65535 as requested):

	1) using LOG:

Oct 30 23:14:34 tux vmunix: :d0:87:60:0SC6.3.310DT121812LN4 O=x0PE=x0TL4 D0POOTPST8 P=94 IDW0RS00 C S RP0
Oct 30 23:14:34 tux vmunix: 6DO NU:I=t0OT A=01:3e:79:01:fe:b2:80 R=3267.9 S=9.6.. E=0TS00 RC00 T=4I= RT=C P=0DT585WNO= E=x0AKRTUG= 

	2) using NFLOG (syslog emul):

Oct 30 23:14:34 tux DROP INPUT:  IN=eth0 OUT= MAC=00:18:f3:e4:47:9f:00:1d:0f:e8:7b:26:08:00 SRC=63.236.73.190 DST=192.168.1.2 LEN=40 TOS=00 PREC=0x00 TTL=44 ID=0 PROTO=TCP SPT=80 DPT=59845 SEQ=0 ACK=2739255566 WINDOW=0 ACK RST URGP=0 MARK=0 

Oct 30 23:14:34 tux DROP INPUT:  IN=eth0 OUT= MAC=00:18:f3:e4:47:9f:00:1d:0f:e8:7b:26:08:00 SRC=63.236.73.190 DST=192.168.1.2 LEN=40 TOS=00 PREC=0x00 TTL=44 ID=0 PROTO=TCP SPT=80 DPT=59845 SEQ=0 ACK=2739255566 WINDOW=0 ACK RST URGP=0 MARK=0 

Oct 30 23:14:34 tux DROP INPUT:  IN=eth0 OUT= MAC=00:18:f3:e4:47:9f:00:1d:0f:e8:7b:26:08:00 SRC=63.236.73.190 DST=192.168.1.2 LEN=40 TOS=00 PREC=0x00 TTL=44 ID=0 PROTO=TCP SPT=80 DPT=59845 SEQ=0 ACK=2739255566 WINDOW=0 ACK RST URGP=0 MARK=0 

Oct 30 23:14:34 tux DROP INPUT:  IN=eth0 OUT= MAC=00:18:f3:e4:47:9f:00:1d:0f:e8:7b:26:08:00 SRC=63.236.73.190 DST=192.168.1.2 LEN=40 TOS=00 PREC=0x00 TTL=44 ID=0 PROTO=TCP SPT=80 DPT=59845 SEQ=0 ACK=2739255567 WINDOW=0 ACK RST URGP=0 MARK=0 

	It's interesting to note that NFLOG always give the double of the entries of the "wrong" LOG entries.

	3) and the attached pcap log file.

	I hope that it will give you some hint. Thanks!

-- 

[-- Attachment #2: ulogd-final.pcap.bz2 --]
[-- Type: application/octet-stream, Size: 997 bytes --]

Re: Every other char with LOG netfilter output (bug?)

[Patrick McHardy]

Dâniel Fraga wrote:
> On Thu, 30 Oct 2008 08:15:14 +0100
> Patrick McHardy <kaber@trash.net> wrote:
> 
>> One thing you need is to specify the amount of bytes you want transfered
>> to userspace:
>>
>> iptables ... -j NFLOG --nflog-range 65535
> 
> 	Another one (now with --nflog-range 65535 as requested):
> 
> 	1) using LOG:
> 
> Oct 30 23:14:34 tux vmunix: :d0:87:60:0SC6.3.310DT121812LN4 O=x0PE=x0TL4 D0POOTPST8 P=94 IDW0RS00 C S RP0
> Oct 30 23:14:34 tux vmunix: 6DO NU:I=t0OT A=01:3e:79:01:fe:b2:80 R=3267.9 S=9.6.. E=0TS00 RC00 T=4I= RT=C P=0DT585WNO= E=x0AKRTUG= 
> 
> 	2) using NFLOG (syslog emul):
> 
> Oct 30 23:14:34 tux DROP INPUT:  IN=eth0 OUT= MAC=00:18:f3:e4:47:9f:00:1d:0f:e8:7b:26:08:00 SRC=63.236.73.190 DST=192.168.1.2 LEN=40 TOS=00 PREC=0x00 TTL=44 ID=0 PROTO=TCP SPT=80 DPT=59845 SEQ=0 ACK=2739255566 WINDOW=0 ACK RST URGP=0 MARK=0 
> 
> Oct 30 23:14:34 tux DROP INPUT:  IN=eth0 OUT= MAC=00:18:f3:e4:47:9f:00:1d:0f:e8:7b:26:08:00 SRC=63.236.73.190 DST=192.168.1.2 LEN=40 TOS=00 PREC=0x00 TTL=44 ID=0 PROTO=TCP SPT=80 DPT=59845 SEQ=0 ACK=2739255566 WINDOW=0 ACK RST URGP=0 MARK=0 
> 
> Oct 30 23:14:34 tux DROP INPUT:  IN=eth0 OUT= MAC=00:18:f3:e4:47:9f:00:1d:0f:e8:7b:26:08:00 SRC=63.236.73.190 DST=192.168.1.2 LEN=40 TOS=00 PREC=0x00 TTL=44 ID=0 PROTO=TCP SPT=80 DPT=59845 SEQ=0 ACK=2739255566 WINDOW=0 ACK RST URGP=0 MARK=0 
> 
> Oct 30 23:14:34 tux DROP INPUT:  IN=eth0 OUT= MAC=00:18:f3:e4:47:9f:00:1d:0f:e8:7b:26:08:00 SRC=63.236.73.190 DST=192.168.1.2 LEN=40 TOS=00 PREC=0x00 TTL=44 ID=0 PROTO=TCP SPT=80 DPT=59845 SEQ=0 ACK=2739255567 WINDOW=0 ACK RST URGP=0 MARK=0 
> 
> 	It's interesting to note that NFLOG always give the double of the entries of the "wrong" LOG entries.
> 
> 	3) and the attached pcap log file.
> 
> 	I hope that it will give you some hint. Thanks!

It doesn't explain why the LOG output is corrupted, but it seems
the hanging connections are caused by RST packets that are considered
INVALID.

Please enable conntrack debugging by executing:

echo 255 >/proc/sys/net/netfilter/nf_conntrack_log_invalid

so we can see why these packets are considered invalid.
--
To unsubscribe from this list: send the line "unsubscribe netfilter-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Every other char with LOG netfilter output (bug?)

[Dâniel Fraga]

On Mon, 03 Nov 2008 13:42:32 +0100
Patrick McHardy <kaber@trash.net> wrote:

> It doesn't explain why the LOG output is corrupted, but it seems
> the hanging connections are caused by RST packets that are considered
> INVALID.
> 
> Please enable conntrack debugging by executing:
> 
> echo 255 >/proc/sys/net/netfilter/nf_conntrack_log_invalid
> 
> so we can see why these packets are considered invalid.

	Hi Patrick, problem solved. The problem was syslogd. :(

	Thanks ;)

--