[Bridge] bridge breaks loopback on 2.4.22

[Bridge] bridge breaks loopback on 2.4.22

[Santiago Garcia Mantinan]

Hi!

Since the change to 2.4.22 I've been experimenting problems here, after
many tests I have seen what I think is the problem that is causing this.

The problem I'm seing is the loopback starts loosing packages, I don't know
if this could also happen on other interfaces. I'm testing this by starting
a:
	tcpdump -n -i lo port
then a:
	nc -n -l port >/dev/null
and a:
	nc localhost port </dev/zero

If everything is fine my cpu goes to 100% and I see the packages all the way
in my tcpdump screen, great. But there are sometimes when this doesn't go
smooth and the tcpdump starts to show only one or two packages each N
seconds, till it ends up showing the resend of the last package which is
never acknowledged, you can even see that the timings of this packages that
are being repeated match those of tcp backoff, my cpu charge is then really
really low, nc disconnects after a while, ...

When does this happen?

It took me a while to find this out, but it happens when you have a bridge
interface and one of the ports of the bridge is told to drop packages, like
when they detect a loop in the net and an interface is set to a blocking
state.

Of course that the loopback is not a part of any bridge in any of my setups,
and I've seen this in a couple of machines, one SMP and the other one single
micro, 2.4.21 worked ok, at least I could not reproduce this on that one. If
the interfaces have been in a forwarding state all the time since the bridge
was setup, without being in a blocking state, then this problem does not
seem to happen.

I believe that the changes the bridge went through from 2.4.21 to 2.4.22 are
to blame on this one, but this is just a guess.

Hope we can find a fix for this so that it is integrated in 2.4.23 kernel,
I'll be happy to make any tests you want to track this farther down.

Regards...
-- 
Manty/BestiaTester -> http://manty.net

bridge breaks loopback on 2.4.22

[Santiago Garcia Mantinan]

Hi!

Since the change to 2.4.22 I've been experimenting problems here, after
many tests I have seen what I think is the problem that is causing this.

The problem I'm seing is the loopback starts loosing packages, I don't know
if this could also happen on other interfaces. I'm testing this by starting
a:
	tcpdump -n -i lo port
then a:
	nc -n -l port >/dev/null
and a:
	nc localhost port </dev/zero

If everything is fine my cpu goes to 100% and I see the packages all the way
in my tcpdump screen, great. But there are sometimes when this doesn't go
smooth and the tcpdump starts to show only one or two packages each N
seconds, till it ends up showing the resend of the last package which is
never acknowledged, you can even see that the timings of this packages that
are being repeated match those of tcp backoff, my cpu charge is then really
really low, nc disconnects after a while, ...

When does this happen?

It took me a while to find this out, but it happens when you have a bridge
interface and one of the ports of the bridge is told to drop packages, like
when they detect a loop in the net and an interface is set to a blocking
state.

Of course that the loopback is not a part of any bridge in any of my setups,
and I've seen this in a couple of machines, one SMP and the other one single
micro, 2.4.21 worked ok, at least I could not reproduce this on that one. If
the interfaces have been in a forwarding state all the time since the bridge
was setup, without being in a blocking state, then this problem does not
seem to happen.

I believe that the changes the bridge went through from 2.4.21 to 2.4.22 are
to blame on this one, but this is just a guess.

Hope we can find a fix for this so that it is integrated in 2.4.23 kernel,
I'll be happy to make any tests you want to track this farther down.

Regards...
-- 
Manty/BestiaTester -> http://manty.net

Re: [Bridge] bridge breaks loopback on 2.4.22

[Stephen Hemminger]

On Sat, 27 Sep 2003 22:22:01 +0200
Santiago Garcia Mantinan <manty@manty.net> wrote:

> Hi!
> 
> Since the change to 2.4.22 I've been experimenting problems here, after
> many tests I have seen what I think is the problem that is causing this.
> 
> The problem I'm seing is the loopback starts loosing packages, I don't know
> if this could also happen on other interfaces. I'm testing this by starting
> a:
> 	tcpdump -n -i lo port
> then a:
> 	nc -n -l port >/dev/null
> and a:
> 	nc localhost port </dev/zero
> 
> If everything is fine my cpu goes to 100% and I see the packages all the way
> in my tcpdump screen, great. But there are sometimes when this doesn't go
> smooth and the tcpdump starts to show only one or two packages each N
> seconds, till it ends up showing the resend of the last package which is
> never acknowledged, you can even see that the timings of this packages that
> are being repeated match those of tcp backoff, my cpu charge is then really
> really low, nc disconnects after a while, ...
> 
> When does this happen?
> 
> It took me a while to find this out, but it happens when you have a bridge
> interface and one of the ports of the bridge is told to drop packages, like
> when they detect a loop in the net and an interface is set to a blocking
> state.
> 
> Of course that the loopback is not a part of any bridge in any of my setups,
> and I've seen this in a couple of machines, one SMP and the other one single
> micro, 2.4.21 worked ok, at least I could not reproduce this on that one. If
> the interfaces have been in a forwarding state all the time since the bridge
> was setup, without being in a blocking state, then this problem does not
> seem to happen.
> 
> I believe that the changes the bridge went through from 2.4.21 to 2.4.22 are
> to blame on this one, but this is just a guess.
> 
> Hope we can find a fix for this so that it is integrated in 2.4.23 kernel,
> I'll be happy to make any tests you want to track this farther down.


What kind of hardware do you have? what are the ethernet's you are trying
to bridge?  

There haven't been a many changes at all to the bridging code, and you could
try building the 2.4.21 bridge code into a 2.4.22 kernel.

When cpu goes 100% could you get a backtrace (with sysrq-t)? 

[Bridge] Re: bridge breaks loopback on 2.4.22

[Marcelo Tosatti]

Stephen, 

Have you looked into this? 

Thank you 

On Sat, 27 Sep 2003, Santiago Garcia Mantinan wrote:

> Hi!
> 
> Since the change to 2.4.22 I've been experimenting problems here, after
> many tests I have seen what I think is the problem that is causing this.
> 
> The problem I'm seing is the loopback starts loosing packages, I don't know
> if this could also happen on other interfaces. I'm testing this by starting
> a:
> 	tcpdump -n -i lo port
> then a:
> 	nc -n -l port >/dev/null
> and a:
> 	nc localhost port </dev/zero
> 
> If everything is fine my cpu goes to 100% and I see the packages all the way
> in my tcpdump screen, great. But there are sometimes when this doesn't go
> smooth and the tcpdump starts to show only one or two packages each N
> seconds, till it ends up showing the resend of the last package which is
> never acknowledged, you can even see that the timings of this packages that
> are being repeated match those of tcp backoff, my cpu charge is then really
> really low, nc disconnects after a while, ...
> 
> When does this happen?
> 
> It took me a while to find this out, but it happens when you have a bridge
> interface and one of the ports of the bridge is told to drop packages, like
> when they detect a loop in the net and an interface is set to a blocking
> state.
> 
> Of course that the loopback is not a part of any bridge in any of my setups,
> and I've seen this in a couple of machines, one SMP and the other one single
> micro, 2.4.21 worked ok, at least I could not reproduce this on that one. If
> the interfaces have been in a forwarding state all the time since the bridge
> was setup, without being in a blocking state, then this problem does not
> seem to happen.
> 
> I believe that the changes the bridge went through from 2.4.21 to 2.4.22 are
> to blame on this one, but this is just a guess.
> 
> Hope we can find a fix for this so that it is integrated in 2.4.23 kernel,
> I'll be happy to make any tests you want to track this farther down.
> 
> Regards...
> 

Re: bridge breaks loopback on 2.4.22

[Marcelo Tosatti]

Stephen, 

Have you looked into this? 

Thank you 

On Sat, 27 Sep 2003, Santiago Garcia Mantinan wrote:

> Hi!
> 
> Since the change to 2.4.22 I've been experimenting problems here, after
> many tests I have seen what I think is the problem that is causing this.
> 
> The problem I'm seing is the loopback starts loosing packages, I don't know
> if this could also happen on other interfaces. I'm testing this by starting
> a:
> 	tcpdump -n -i lo port
> then a:
> 	nc -n -l port >/dev/null
> and a:
> 	nc localhost port </dev/zero
> 
> If everything is fine my cpu goes to 100% and I see the packages all the way
> in my tcpdump screen, great. But there are sometimes when this doesn't go
> smooth and the tcpdump starts to show only one or two packages each N
> seconds, till it ends up showing the resend of the last package which is
> never acknowledged, you can even see that the timings of this packages that
> are being repeated match those of tcp backoff, my cpu charge is then really
> really low, nc disconnects after a while, ...
> 
> When does this happen?
> 
> It took me a while to find this out, but it happens when you have a bridge
> interface and one of the ports of the bridge is told to drop packages, like
> when they detect a loop in the net and an interface is set to a blocking
> state.
> 
> Of course that the loopback is not a part of any bridge in any of my setups,
> and I've seen this in a couple of machines, one SMP and the other one single
> micro, 2.4.21 worked ok, at least I could not reproduce this on that one. If
> the interfaces have been in a forwarding state all the time since the bridge
> was setup, without being in a blocking state, then this problem does not
> seem to happen.
> 
> I believe that the changes the bridge went through from 2.4.21 to 2.4.22 are
> to blame on this one, but this is just a guess.
> 
> Hope we can find a fix for this so that it is integrated in 2.4.23 kernel,
> I'll be happy to make any tests you want to track this farther down.
> 
> Regards...
> 

Re: [Bridge] bridge breaks loopback on 2.4.22

[Santiago Garcia Mantinan]

> What kind of hardware do you have? what are the ethernet's you are trying
> to bridge?  

I think this doesn't matter, but right now on the machines I'm seing this
I'm bridging a 100Mb segment (8139too driver) with a 10Mb segment (ne.c
driver), the 10Mb segment carries no trafic at all and is only there for
some old machines (turned off all the time) and in case something happens to
the 100Mb switch.

However, I have some other cards around, I could test with them if you think
that could matter.

> There haven't been a many changes at all to the bridging code, and you could
> try building the 2.4.21 bridge code into a 2.4.22 kernel.

The changes weren't a lot, but something broke, I could not test to build
2.4.21 bridge into 2.4.22 till today, I have just done it and 2.4.22 works
ok like that. What I did is replace net/bridge from 2.4.22 with the one from
2.4.21, works like a charm.

> When cpu goes 100% could you get a backtrace (with sysrq-t)? 

This is ok, I mean, cpu must go 100%, there is nothing wrong with that, if
I'm doing a netcat from /dev/zero into the loopback and out to another
netcat and then to /dev/null a full cpu load is expected, what was not
expected was the 0% cpu load I get when the loopback looses packages and the
netcats start to wait for the kernel to deliver the packages.

I believe anybody can test this, just compile a 2.4.22 with the bridge code
into a box with two network cards, setup a bridge on the two cards and
enable stp, then plug the two cards into the same switch and that should do
it.

Well, I hope this clarifies the thing a bit, if you need any other tests
just ask for them.
-- 
Manty/BestiaTester -> http://manty.net

[Bridge] Re: bridge breaks loopback on 2.4.22

[Hannes Schulz]

At 22:22 Uhr +0200 27.09.2003, Santiago Garcia Mantinan wrote:
>Hi!
>
>Since the change to 2.4.22 I've been experimenting problems here, after
>many tests I have seen what I think is the problem that is causing this.
>

I use 2.4.23-pre3 + 2 bridging related patches:
shemminger	1.1109.2.4 
	[BRIDGE]: Clear hw checksum flags when bridging.
karlis	1.1063.40.5	[BRIDGE]: kfree --> kfree_skb.
[both of them are in 2.4.23-pre4]

I was able to reproduce this only once: I did a ^Z on the bash of the 
listening 'nc':
uml:~# ps -o pid,stat,cmd,wchan=WIDE-WCHAN-COLUMN 2179 2188
   PID STAT CMD              WIDE-WCHAN-COLUMN
  2179 T    nc -n -l -p 8888 signal
  2188 S    nc localhost 888 wait_for_tcp_memory

It didn't continue when I sent a SIGCONT but stayed in 'T'-state. 
Then I did a 'fg':
uml:~# ps -o pid,stat,cmd,wchan=WIDE-WCHAN-COLUMN 2179 2188
   PID STAT CMD              WIDE-WCHAN-COLUMN
  2179 S    nc -n -l -p 8888 read_chan
  2188 S    nc localhost 888 wait_for_tcp_memory

I thought that 'read_chan' is stange an hit Return. Then everything 
resumed back to normal (i.e. tcpdump shows lots of packets).

I have 3 bridges active and one of them has blocked port, but I don't 
think this is related to the bridging code.


Perhaps you could try again with 2.4.23-pre[456].


Hannes

[Bridge] Re: bridge breaks loopback on 2.4.22

[Stephen Hemminger]

When it fails are there any errors in the TCP stats or loopback driver?
Look at 'netstat -s -p tcp' and 'netstat -i lo'

[Bridge] Re: bridge breaks loopback on 2.4.22

[Santiago Garcia Mantinan]

> Perhaps you could try again with 2.4.23-pre[456].

I have tested with 2.4.23-pre6 and the problem seems fixed, in fact, I
tested 2.4.22 with 2.4.23-pre6 bridge, which means a minimal patch, an it
worked well also, thanks for your sugestion ;-)

So I believe that the problem was really in the bridge code but it seems
solved, now I only wish somebody could explain me how this bug in the bridge
code that was fixed in a little patch could be affecting the loopback :-?

Regards...
-- 
Manty/BestiaTester -> http://manty.net

PS: I'm replying Stephen in another mail with more data.

[Bridge] Re: bridge breaks loopback on 2.4.22

[Santiago Garcia Mantinan]

On Oct 02 2003, Stephen Hemminger wrote:
> When it fails are there any errors in the TCP stats or loopback driver?
> Look at 'netstat -s -p tcp' and 'netstat -i lo'

As you may have read in the message I have just replied to, the problem
seems solved in 1.4.23pre6 with the small patch to the bridge code that has
been applied, I'm commenting this at the end, first I'm pasting all the info
that I have recovered to try to find an explanation for this, I still search
an answer to how can this bug in the bridge affect the loopback :-?

First what drove me to say that packages were being lost in the loopback,
this is the output of a "tcpdump -n -i lo port 6000" when doing the netcat
to port 6000 where the other netcat is listening:

....
13:44:13.512372 127.0.0.1.6000 > 127.0.0.1.1028: . ack 3760129 win 32768 <nop,nop,timestamp 35089 35089> (DF)
13:44:13.720021 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 35110 35089> (DF)
13:44:14.140045 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 35152 35089> (DF)
13:44:14.980036 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 35236 35089> (DF)
13:44:16.660039 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 35404 35089> (DF)
13:44:20.020063 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 35740 35089> (DF)
13:44:26.740037 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 36412 35089> (DF)
13:44:40.180042 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 37756 35089> (DF)
13:45:07.060042 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 40444 35089> (DF)
13:46:00.820051 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 45820 35089> (DF)
13:47:48.340031 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 56572 35089> (DF)
13:49:48.340022 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 68572 35089> (DF)
13:51:48.340030 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 80572 35089> (DF)
13:53:48.340022 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 92572 35089> (DF)
13:55:48.340070 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 104572 35089> (DF)
13:57:48.340021 127.0.0.1.1028 > 127.0.0.1.6000: P 3801089:3817473(16384) ack 1 win 32767 <nop,nop,timestamp 116572 35089> (DF)

The one that is sending the info is the one on port 1028, he has already
sent some packages, then he receives an ack of his last package and tries to
send the next one, but it seems like the package never gets to the listener,
as there is no ack and the package is repeated all the time for more than 13
minutes.

This is what you asked for, the netstat info for tcp:
Tcp:
    9 active connections openings
    2 passive connection openings
    0 failed connection attempts
    1 connection resets received
    3 connections established
    4081 segments received
    5553 segments send out
    15 segments retransmited
    0 bad segments received.
    0 resets sent
TcpExt:
    6 TCP sockets finished time wait in fast timer
    82 delayed acks sent
    1 delayed acks further delayed because of locked socket
    65 packets directly queued to recvmsg prequeue.
    1294 of bytes directly received from prequeue
    3363 packet headers predicted
    1 packets header predicted and directly queued to user
    33 acknowledgments not containing data received
    2283 predicted acknowledgments
    0 TCP data loss events
    1 other TCP timeouts
    1 times receiver scheduled too late for direct processing
    1 connections aborted due to timeout

And this is the netstat info for the loopback:
Iface   MTU Met   RX-OK RX-ERR RX-DRP RX-OVR   TX-OK TX-ERR TX-DRP TX-OVR Flg
lo    16436 0       909      0      0      0     909      0      0      0 LRU

The problem went away when I replaced the bridge code in 2.4.22 with the one
from 2.4.23-test6, so, after seing that this fixed the problem I did a diff
and found that the only diffs were just two lines:

diff -ru bridge.2422/br_forward.c bridge/br_forward.c
--- bridge.2422/br_forward.c	2002-08-03 02:39:46.000000000 +0200
+++ bridge/br_forward.c	2003-10-03 19:46:35.000000000 +0200
@@ -59,6 +59,7 @@
 
 	indev = skb->dev;
 	skb->dev = to->dev;
+	skb->ip_summed = CHECKSUM_NONE;
 
 	NF_HOOK(PF_BRIDGE, NF_BR_FORWARD, skb, indev, skb->dev,
 			__br_forward_finish);
diff -ru bridge.2422/br_stp_bpdu.c bridge/br_stp_bpdu.c
--- bridge.2422/br_stp_bpdu.c	2003-08-25 13:44:44.000000000 +0200
+++ bridge/br_stp_bpdu.c	2003-10-03 19:46:35.000000000 +0200
@@ -194,6 +194,6 @@
 	}
 
  err:
-	kfree(skb);
+	kfree_skb(skb);
 	return 0;
 }

So, now I'm asking myself, how can this bug that is fixed by these two lines
in the bridge code, be affecting my loopback?

Anybody can explain this, please?

Thanks in advance and thanks for all your help as well.

Regards...
-- 
Manty/BestiaTester -> http://manty.net

[Bridge] Re: bridge breaks loopback on 2.4.22

[Arnaldo Carvalho de Melo]

Em Sat, Oct 04, 2003 at 05:54:35PM +0200, Santiago Garcia Mantinan escreveu:
> The problem went away when I replaced the bridge code in 2.4.22 with the one
> from 2.4.23-test6, so, after seing that this fixed the problem I did a diff
> and found that the only diffs were just two lines:
> 
> diff -ru bridge.2422/br_forward.c bridge/br_forward.c
> --- bridge.2422/br_forward.c	2002-08-03 02:39:46.000000000 +0200
> +++ bridge/br_forward.c	2003-10-03 19:46:35.000000000 +0200
> @@ -59,6 +59,7 @@
>  
>  	indev = skb->dev;
>  	skb->dev = to->dev;
> +	skb->ip_summed = CHECKSUM_NONE;
>  
>  	NF_HOOK(PF_BRIDGE, NF_BR_FORWARD, skb, indev, skb->dev,
>  			__br_forward_finish);
> diff -ru bridge.2422/br_stp_bpdu.c bridge/br_stp_bpdu.c
> --- bridge.2422/br_stp_bpdu.c	2003-08-25 13:44:44.000000000 +0200
> +++ bridge/br_stp_bpdu.c	2003-10-03 19:46:35.000000000 +0200
> @@ -194,6 +194,6 @@
>  	}
>  
>   err:
> -	kfree(skb);
> +	kfree_skb(skb);
>  	return 0;
>  }
> 
> So, now I'm asking myself, how can this bug that is fixed by these two lines
> in the bridge code, be affecting my loopback?
> 
> Anybody can explain this, please?
> 
> Thanks in advance and thanks for all your help as well.

Well, kfree_skb doesn't frees the sk_buff right away, it looks at its refcnt,
while kfree just puts the area in the pointer in the pool, back to be reused,
so what has happened most probably is that when the skb, that was being shared,
but is now freed by kfree hits the packet sniffer... b00m, or it is being used
for something else or is outright damaged, or both.

I.e. it should be freed after the packet sniffer is done with it, and most
importantly, with the proper destructor, kfree_skb.

- Arnaldo

[Bridge] Re: bridge breaks loopback on 2.4.22

[Santiago Garcia Mantinan]

> but is now freed by kfree hits the packet sniffer... b00m, or it is being used
> for something else or is outright damaged, or both.

Well, the thing is that the problem here was that the loopback was behaving
like it was loosing packages, nothing to do with the packet sniffer, in
fact, very same thing (packets lost and connection interrupted) happened
without putting the sniffer in the middle, the sniffer was put there just to
diagnose the problem, it didn't have any effect on the problem.

Thanks for your info!

Regards...
-- 
Manty/BestiaTester -> http://manty.net