* Crazy TCP bug (keepalive flood?) in 2.6.32?
@ 2009-12-09 18:51 Denys Fedoryshchenko
2009-12-10 8:24 ` Ilpo Järvinen
0 siblings, 1 reply; 15+ messages in thread
From: Denys Fedoryshchenko @ 2009-12-09 18:51 UTC (permalink / raw)
To: netdev
Hi
I did upgrade of my lusca(squid) proxies and notice that some users getting up
to 8-15 Mbit/s flood (while they are shaped to 128Kbit/s). After tracing i end
up on one of proxies host and seems it is bug in kernel tcp stack.
I check packets inside - it is same repeating content (and even same tcp
sequence, so it is almost sure tcp bug). Sender also ignoring ICMP unreachable
packets and continue flooding destination
Here is some examples
ss output for corresponding entry
ESTAB 0 8267 194.146.153.114:8080 172.16.67.243:2512
20:32:08.491470 IP (tos 0x0, ttl 64, id 49493, offset 0, flags [DF], proto TCP
(6), length 655)
194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
(correct), seq 0:615, ack 1, win 7504, length 615
20:32:08.492487 IP (tos 0x0, ttl 64, id 49494, offset 0, flags [DF], proto TCP
(6), length 655)
194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
(correct), seq 0:615, ack 1, win 7504, length 615
20:32:08.493468 IP (tos 0x0, ttl 64, id 49495, offset 0, flags [DF], proto TCP
(6), length 655)
194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
(correct), seq 0:615, ack 1, win 7504, length 615
20:32:08.494463 IP (tos 0x0, ttl 64, id 49496, offset 0, flags [DF], proto TCP
(6), length 655)
194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
(correct), seq 0:615, ack 1, win 7504, length 615
20:32:08.495463 IP (tos 0x0, ttl 64, id 49497, offset 0, flags [DF], proto TCP
(6), length 655)
194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
(correct), seq 0:615, ack 1, win 7504, length 615
20:32:08.496467 IP (tos 0x0, ttl 64, id 49498, offset 0, flags [DF], proto TCP
(6), length 655)
One more
20:36:13.310718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
win 7469, length 1440
20:36:13.311725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
win 7469, length 1440
20:36:13.312729 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
win 7469, length 1440
20:36:13.313717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
win 7469, length 1440
20:36:13.314717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
win 7469, length 1440
20:36:13.315718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
win 7469, length 1440
20:36:13.316725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
win 7469, length 1440
I run multiple times ss
ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
timer:(on,,172) uid:101 ino:4772596 sk:c0ce84c0
ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
timer:(on,,43) uid:101 ino:4772596 sk:c0ce84c0
ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
timer:(on,,17) uid:101 ino:4772596 sk:c0ce84c0
After i kill squid it will switch socket to FIN-WAIT state and flood will
stop.
Some sysctl tuning done during boot (maybe related)
sysctl -w net.ipv4.tcp_frto=2
sysctl -w net.ipv4.tcp_frto_response=2
And most probably it is related to keepalive. I have it set on this socket:
http_port 8080 transparent tcpkeepalive=30,30,60 http11
>From manual
#<-----> tcpkeepalive[=idle,interval,timeout]
#<-----><------><------>Enable TCP keepalive probes of idle connections
#<-----><------><------>idle is the initial time before TCP starts probing
#<-----><------><------>the connection, interval how often to probe, and
#<-----><------><------>timeout the time before giving up.
I am not able to reproduce reliably bug, but it is appearing on different
cluster pc's randomly for single connection each 5-10 minutes (around 8000
established connections to each at moment, 8 pc's in cluster) and dissapearing
after 10-50 seconds of flood.
^ permalink raw reply [flat|nested] 15+ messages in thread* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2009-12-09 18:51 Crazy TCP bug (keepalive flood?) in 2.6.32? Denys Fedoryshchenko
@ 2009-12-10 8:24 ` Ilpo Järvinen
2009-12-10 8:28 ` Ilpo Järvinen
0 siblings, 1 reply; 15+ messages in thread
From: Ilpo Järvinen @ 2009-12-10 8:24 UTC (permalink / raw)
To: Denys Fedoryshchenko, Damian Lukowski; +Cc: Netdev
Cc Damian.
On Wed, 9 Dec 2009, Denys Fedoryshchenko wrote:
> Hi
>
> I did upgrade of my lusca(squid) proxies and notice that some users getting up
> to 8-15 Mbit/s flood (while they are shaped to 128Kbit/s). After tracing i end
> up on one of proxies host and seems it is bug in kernel tcp stack.
>
> I check packets inside - it is same repeating content (and even same tcp
> sequence, so it is almost sure tcp bug). Sender also ignoring ICMP unreachable
> packets and continue flooding destination
>
> Here is some examples
> ss output for corresponding entry
>
> ESTAB 0 8267 194.146.153.114:8080 172.16.67.243:2512
>
>
> 20:32:08.491470 IP (tos 0x0, ttl 64, id 49493, offset 0, flags [DF], proto TCP
> (6), length 655)
> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> (correct), seq 0:615, ack 1, win 7504, length 615
> 20:32:08.492487 IP (tos 0x0, ttl 64, id 49494, offset 0, flags [DF], proto TCP
> (6), length 655)
> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> (correct), seq 0:615, ack 1, win 7504, length 615
> 20:32:08.493468 IP (tos 0x0, ttl 64, id 49495, offset 0, flags [DF], proto TCP
> (6), length 655)
> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> (correct), seq 0:615, ack 1, win 7504, length 615
> 20:32:08.494463 IP (tos 0x0, ttl 64, id 49496, offset 0, flags [DF], proto TCP
> (6), length 655)
> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> (correct), seq 0:615, ack 1, win 7504, length 615
> 20:32:08.495463 IP (tos 0x0, ttl 64, id 49497, offset 0, flags [DF], proto TCP
> (6), length 655)
> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> (correct), seq 0:615, ack 1, win 7504, length 615
> 20:32:08.496467 IP (tos 0x0, ttl 64, id 49498, offset 0, flags [DF], proto TCP
> (6), length 655)
>
>
> One more
> 20:36:13.310718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> win 7469, length 1440
> 20:36:13.311725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> win 7469, length 1440
> 20:36:13.312729 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> win 7469, length 1440
> 20:36:13.313717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> win 7469, length 1440
> 20:36:13.314717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> win 7469, length 1440
> 20:36:13.315718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> win 7469, length 1440
> 20:36:13.316725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> win 7469, length 1440
>
> I run multiple times ss
>
> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> timer:(on,,172) uid:101 ino:4772596 sk:c0ce84c0
> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> timer:(on,,43) uid:101 ino:4772596 sk:c0ce84c0
> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> timer:(on,,17) uid:101 ino:4772596 sk:c0ce84c0
>
> After i kill squid it will switch socket to FIN-WAIT state and flood will
> stop.
>
> Some sysctl tuning done during boot (maybe related)
> sysctl -w net.ipv4.tcp_frto=2
> sysctl -w net.ipv4.tcp_frto_response=2
>
> And most probably it is related to keepalive. I have it set on this socket:
> http_port 8080 transparent tcpkeepalive=30,30,60 http11
>
> From manual
> #<-----> tcpkeepalive[=idle,interval,timeout]
> #<-----><------><------>Enable TCP keepalive probes of idle connections
> #<-----><------><------>idle is the initial time before TCP starts probing
> #<-----><------><------>the connection, interval how often to probe, and
> #<-----><------><------>timeout the time before giving up.
>
> I am not able to reproduce reliably bug, but it is appearing on different
> cluster pc's randomly for single connection each 5-10 minutes (around 8000
> established connections to each at moment, 8 pc's in cluster) and dissapearing
> after 10-50 seconds of flood.
Damian, can you please take a look. ...It's a bit weird after a very brief
look (as if RTO would trigger way too often). Maybe its backoff is broken
now?
--
i.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2009-12-10 8:24 ` Ilpo Järvinen
@ 2009-12-10 8:28 ` Ilpo Järvinen
2009-12-10 8:50 ` Ilpo Järvinen
0 siblings, 1 reply; 15+ messages in thread
From: Ilpo Järvinen @ 2009-12-10 8:28 UTC (permalink / raw)
To: Denys Fedoryshchenko, Damian Lukowski; +Cc: Netdev
[-- Attachment #1: Type: TEXT/PLAIN, Size: 4662 bytes --]
On Thu, 10 Dec 2009, Ilpo Järvinen wrote:
> Cc Damian.
>
> On Wed, 9 Dec 2009, Denys Fedoryshchenko wrote:
>
> > Hi
> >
> > I did upgrade of my lusca(squid) proxies and notice that some users getting up
> > to 8-15 Mbit/s flood (while they are shaped to 128Kbit/s). After tracing i end
> > up on one of proxies host and seems it is bug in kernel tcp stack.
> >
> > I check packets inside - it is same repeating content (and even same tcp
> > sequence, so it is almost sure tcp bug). Sender also ignoring ICMP unreachable
> > packets and continue flooding destination
> >
> > Here is some examples
> > ss output for corresponding entry
> >
> > ESTAB 0 8267 194.146.153.114:8080 172.16.67.243:2512
> >
> >
> > 20:32:08.491470 IP (tos 0x0, ttl 64, id 49493, offset 0, flags [DF], proto TCP
> > (6), length 655)
> > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > (correct), seq 0:615, ack 1, win 7504, length 615
> > 20:32:08.492487 IP (tos 0x0, ttl 64, id 49494, offset 0, flags [DF], proto TCP
> > (6), length 655)
> > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > (correct), seq 0:615, ack 1, win 7504, length 615
> > 20:32:08.493468 IP (tos 0x0, ttl 64, id 49495, offset 0, flags [DF], proto TCP
> > (6), length 655)
> > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > (correct), seq 0:615, ack 1, win 7504, length 615
> > 20:32:08.494463 IP (tos 0x0, ttl 64, id 49496, offset 0, flags [DF], proto TCP
> > (6), length 655)
> > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > (correct), seq 0:615, ack 1, win 7504, length 615
> > 20:32:08.495463 IP (tos 0x0, ttl 64, id 49497, offset 0, flags [DF], proto TCP
> > (6), length 655)
> > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > (correct), seq 0:615, ack 1, win 7504, length 615
> > 20:32:08.496467 IP (tos 0x0, ttl 64, id 49498, offset 0, flags [DF], proto TCP
> > (6), length 655)
> >
> >
> > One more
> > 20:36:13.310718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > win 7469, length 1440
> > 20:36:13.311725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > win 7469, length 1440
> > 20:36:13.312729 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > win 7469, length 1440
> > 20:36:13.313717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > win 7469, length 1440
> > 20:36:13.314717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > win 7469, length 1440
> > 20:36:13.315718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > win 7469, length 1440
> > 20:36:13.316725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > win 7469, length 1440
> >
> > I run multiple times ss
> >
> > ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> > timer:(on,,172) uid:101 ino:4772596 sk:c0ce84c0
> > ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> > timer:(on,,43) uid:101 ino:4772596 sk:c0ce84c0
> > ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> > timer:(on,,17) uid:101 ino:4772596 sk:c0ce84c0
> >
> > After i kill squid it will switch socket to FIN-WAIT state and flood will
> > stop.
> >
> > Some sysctl tuning done during boot (maybe related)
> > sysctl -w net.ipv4.tcp_frto=2
> > sysctl -w net.ipv4.tcp_frto_response=2
> >
> > And most probably it is related to keepalive. I have it set on this socket:
> > http_port 8080 transparent tcpkeepalive=30,30,60 http11
> >
> > From manual
> > #<-----> tcpkeepalive[=idle,interval,timeout]
> > #<-----><------><------>Enable TCP keepalive probes of idle connections
> > #<-----><------><------>idle is the initial time before TCP starts probing
> > #<-----><------><------>the connection, interval how often to probe, and
> > #<-----><------><------>timeout the time before giving up.
> >
> > I am not able to reproduce reliably bug, but it is appearing on different
> > cluster pc's randomly for single connection each 5-10 minutes (around 8000
> > established connections to each at moment, 8 pc's in cluster) and dissapearing
> > after 10-50 seconds of flood.
>
> Damian, can you please take a look. ...It's a bit weird after a very brief
> look (as if RTO would trigger way too often). Maybe its backoff is broken
> now?
...I meant broken when keepalives are in use.
--
i.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2009-12-10 8:28 ` Ilpo Järvinen
@ 2009-12-10 8:50 ` Ilpo Järvinen
2009-12-10 10:05 ` Damian Lukowski
0 siblings, 1 reply; 15+ messages in thread
From: Ilpo Järvinen @ 2009-12-10 8:50 UTC (permalink / raw)
To: Denys Fedoryshchenko, Damian Lukowski; +Cc: Netdev
[-- Attachment #1: Type: TEXT/PLAIN, Size: 5143 bytes --]
On Thu, 10 Dec 2009, Ilpo Järvinen wrote:
> On Thu, 10 Dec 2009, Ilpo Järvinen wrote:
>
> > Cc Damian.
> >
> > On Wed, 9 Dec 2009, Denys Fedoryshchenko wrote:
> >
> > > Hi
> > >
> > > I did upgrade of my lusca(squid) proxies and notice that some users getting up
> > > to 8-15 Mbit/s flood (while they are shaped to 128Kbit/s). After tracing i end
> > > up on one of proxies host and seems it is bug in kernel tcp stack.
> > >
> > > I check packets inside - it is same repeating content (and even same tcp
> > > sequence, so it is almost sure tcp bug). Sender also ignoring ICMP unreachable
> > > packets and continue flooding destination
> > >
> > > Here is some examples
> > > ss output for corresponding entry
> > >
> > > ESTAB 0 8267 194.146.153.114:8080 172.16.67.243:2512
> > >
> > >
> > > 20:32:08.491470 IP (tos 0x0, ttl 64, id 49493, offset 0, flags [DF], proto TCP
> > > (6), length 655)
> > > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > > (correct), seq 0:615, ack 1, win 7504, length 615
> > > 20:32:08.492487 IP (tos 0x0, ttl 64, id 49494, offset 0, flags [DF], proto TCP
> > > (6), length 655)
> > > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > > (correct), seq 0:615, ack 1, win 7504, length 615
> > > 20:32:08.493468 IP (tos 0x0, ttl 64, id 49495, offset 0, flags [DF], proto TCP
> > > (6), length 655)
> > > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > > (correct), seq 0:615, ack 1, win 7504, length 615
> > > 20:32:08.494463 IP (tos 0x0, ttl 64, id 49496, offset 0, flags [DF], proto TCP
> > > (6), length 655)
> > > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > > (correct), seq 0:615, ack 1, win 7504, length 615
> > > 20:32:08.495463 IP (tos 0x0, ttl 64, id 49497, offset 0, flags [DF], proto TCP
> > > (6), length 655)
> > > 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> > > (correct), seq 0:615, ack 1, win 7504, length 615
> > > 20:32:08.496467 IP (tos 0x0, ttl 64, id 49498, offset 0, flags [DF], proto TCP
> > > (6), length 655)
> > >
> > >
> > > One more
> > > 20:36:13.310718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > > win 7469, length 1440
> > > 20:36:13.311725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > > win 7469, length 1440
> > > 20:36:13.312729 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > > win 7469, length 1440
> > > 20:36:13.313717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > > win 7469, length 1440
> > > 20:36:13.314717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > > win 7469, length 1440
> > > 20:36:13.315718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > > win 7469, length 1440
> > > 20:36:13.316725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> > > win 7469, length 1440
> > >
> > > I run multiple times ss
> > >
> > > ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> > > timer:(on,,172) uid:101 ino:4772596 sk:c0ce84c0
> > > ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> > > timer:(on,,43) uid:101 ino:4772596 sk:c0ce84c0
> > > ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> > > timer:(on,,17) uid:101 ino:4772596 sk:c0ce84c0
> > >
> > > After i kill squid it will switch socket to FIN-WAIT state and flood will
> > > stop.
> > >
> > > Some sysctl tuning done during boot (maybe related)
> > > sysctl -w net.ipv4.tcp_frto=2
> > > sysctl -w net.ipv4.tcp_frto_response=2
> > >
> > > And most probably it is related to keepalive. I have it set on this socket:
> > > http_port 8080 transparent tcpkeepalive=30,30,60 http11
> > >
> > > From manual
> > > #<-----> tcpkeepalive[=idle,interval,timeout]
> > > #<-----><------><------>Enable TCP keepalive probes of idle connections
> > > #<-----><------><------>idle is the initial time before TCP starts probing
> > > #<-----><------><------>the connection, interval how often to probe, and
> > > #<-----><------><------>timeout the time before giving up.
> > >
> > > I am not able to reproduce reliably bug, but it is appearing on different
> > > cluster pc's randomly for single connection each 5-10 minutes (around 8000
> > > established connections to each at moment, 8 pc's in cluster) and dissapearing
> > > after 10-50 seconds of flood.
> >
> > Damian, can you please take a look. ...It's a bit weird after a very brief
> > look (as if RTO would trigger way too often). Maybe its backoff is broken
> > now?
>
> ...I meant broken when keepalives are in use.
I guess it's that the ICMPs are somehow triggering the
tcp_retransmit_timer call in tcp_ipv4 even though they're not supposed
to do that until the RTO timeout would have fired. I've no idea why
remaining doesn't do what it's supposed to.
--
i.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2009-12-10 8:50 ` Ilpo Järvinen
@ 2009-12-10 10:05 ` Damian Lukowski
2009-12-10 10:24 ` Ilpo Järvinen
0 siblings, 1 reply; 15+ messages in thread
From: Damian Lukowski @ 2009-12-10 10:05 UTC (permalink / raw)
To: Ilpo Järvinen; +Cc: Denys Fedoryshchenko, Netdev
Ilpo Järvinen schrieb:
> On Thu, 10 Dec 2009, Ilpo Järvinen wrote:
>
>> On Thu, 10 Dec 2009, Ilpo Järvinen wrote:
>>
>>> Cc Damian.
>>>
>>> On Wed, 9 Dec 2009, Denys Fedoryshchenko wrote:
>>>
>>>> Hi
>>>>
>>>> I did upgrade of my lusca(squid) proxies and notice that some users getting up
>>>> to 8-15 Mbit/s flood (while they are shaped to 128Kbit/s). After tracing i end
>>>> up on one of proxies host and seems it is bug in kernel tcp stack.
>>>>
>>>> I check packets inside - it is same repeating content (and even same tcp
>>>> sequence, so it is almost sure tcp bug). Sender also ignoring ICMP unreachable
>>>> packets and continue flooding destination
By "also" you mean, that the sender is flooding with and without ICMPs?
>>>>
>>>> Here is some examples
>>>> ss output for corresponding entry
>>>>
>>>> ESTAB 0 8267 194.146.153.114:8080 172.16.67.243:2512
>>>>
>>>>
>>>> 20:32:08.491470 IP (tos 0x0, ttl 64, id 49493, offset 0, flags [DF], proto TCP
>>>> (6), length 655)
>>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
>>>> (correct), seq 0:615, ack 1, win 7504, length 615
>>>> 20:32:08.492487 IP (tos 0x0, ttl 64, id 49494, offset 0, flags [DF], proto TCP
>>>> (6), length 655)
>>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
>>>> (correct), seq 0:615, ack 1, win 7504, length 615
>>>> 20:32:08.493468 IP (tos 0x0, ttl 64, id 49495, offset 0, flags [DF], proto TCP
>>>> (6), length 655)
>>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
>>>> (correct), seq 0:615, ack 1, win 7504, length 615
>>>> 20:32:08.494463 IP (tos 0x0, ttl 64, id 49496, offset 0, flags [DF], proto TCP
>>>> (6), length 655)
>>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
>>>> (correct), seq 0:615, ack 1, win 7504, length 615
>>>> 20:32:08.495463 IP (tos 0x0, ttl 64, id 49497, offset 0, flags [DF], proto TCP
>>>> (6), length 655)
>>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
>>>> (correct), seq 0:615, ack 1, win 7504, length 615
>>>> 20:32:08.496467 IP (tos 0x0, ttl 64, id 49498, offset 0, flags [DF], proto TCP
>>>> (6), length 655)
>>>>
>>>>
>>>> One more
>>>> 20:36:13.310718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
>>>> win 7469, length 1440
>>>> 20:36:13.311725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
>>>> win 7469, length 1440
>>>> 20:36:13.312729 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
>>>> win 7469, length 1440
>>>> 20:36:13.313717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
>>>> win 7469, length 1440
>>>> 20:36:13.314717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
>>>> win 7469, length 1440
>>>> 20:36:13.315718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
>>>> win 7469, length 1440
>>>> 20:36:13.316725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
>>>> win 7469, length 1440
>>>>
>>>> I run multiple times ss
>>>>
>>>> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
>>>> timer:(on,,172) uid:101 ino:4772596 sk:c0ce84c0
>>>> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
>>>> timer:(on,,43) uid:101 ino:4772596 sk:c0ce84c0
>>>> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
>>>> timer:(on,,17) uid:101 ino:4772596 sk:c0ce84c0
>>>>
>>>> After i kill squid it will switch socket to FIN-WAIT state and flood will
>>>> stop.
>>>>
>>>> Some sysctl tuning done during boot (maybe related)
>>>> sysctl -w net.ipv4.tcp_frto=2
>>>> sysctl -w net.ipv4.tcp_frto_response=2
>>>>
>>>> And most probably it is related to keepalive. I have it set on this socket:
>>>> http_port 8080 transparent tcpkeepalive=30,30,60 http11
>>>>
>>>> From manual
>>>> #<-----> tcpkeepalive[=idle,interval,timeout]
>>>> #<-----><------><------>Enable TCP keepalive probes of idle connections
>>>> #<-----><------><------>idle is the initial time before TCP starts probing
>>>> #<-----><------><------>the connection, interval how often to probe, and
>>>> #<-----><------><------>timeout the time before giving up.
>>>>
>>>> I am not able to reproduce reliably bug, but it is appearing on different
>>>> cluster pc's randomly for single connection each 5-10 minutes (around 8000
>>>> established connections to each at moment, 8 pc's in cluster) and dissapearing
>>>> after 10-50 seconds of flood.
>>> Damian, can you please take a look. ...It's a bit weird after a very brief
>>> look (as if RTO would trigger way too often). Maybe its backoff is broken
>>> now?
>> ...I meant broken when keepalives are in use.
>
> I guess it's that the ICMPs are somehow triggering the
> tcp_retransmit_timer call in tcp_ipv4 even though they're not supposed
> to do that until the RTO timeout would have fired. I've no idea why
> remaining doesn't do what it's supposed to.
>
Hm.
Those ICMPs will trigger only, if icsk_backoff and retransmits is non-zero.
If that's because of a retransmission (which was thought to be), then
packets_out is non-zero and tcp_probe_timer will return before sending anything.
Correct me, if I'm wrong here.
I'll try to think of a case, where those are non-zero with no packets_out.
Damian
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2009-12-10 10:05 ` Damian Lukowski
@ 2009-12-10 10:24 ` Ilpo Järvinen
2009-12-26 14:54 ` Denys Fedoryshchenko
0 siblings, 1 reply; 15+ messages in thread
From: Ilpo Järvinen @ 2009-12-10 10:24 UTC (permalink / raw)
To: Damian Lukowski; +Cc: Denys Fedoryshchenko, Netdev
[-- Attachment #1: Type: TEXT/PLAIN, Size: 6367 bytes --]
On Thu, 10 Dec 2009, Damian Lukowski wrote:
> Ilpo Järvinen schrieb:
> > On Thu, 10 Dec 2009, Ilpo Järvinen wrote:
> >
> >> On Thu, 10 Dec 2009, Ilpo Järvinen wrote:
> >>
> >>> Cc Damian.
> >>>
> >>> On Wed, 9 Dec 2009, Denys Fedoryshchenko wrote:
> >>>
> >>>> Hi
> >>>>
> >>>> I did upgrade of my lusca(squid) proxies and notice that some users getting up
> >>>> to 8-15 Mbit/s flood (while they are shaped to 128Kbit/s). After tracing i end
> >>>> up on one of proxies host and seems it is bug in kernel tcp stack.
> >>>>
> >>>> I check packets inside - it is same repeating content (and even same tcp
> >>>> sequence, so it is almost sure tcp bug). Sender also ignoring ICMP unreachable
> >>>> packets and continue flooding destination
>
> By "also" you mean, that the sender is flooding with and without ICMPs?
>
> >>>>
> >>>> Here is some examples
> >>>> ss output for corresponding entry
> >>>>
> >>>> ESTAB 0 8267 194.146.153.114:8080 172.16.67.243:2512
> >>>>
> >>>>
> >>>> 20:32:08.491470 IP (tos 0x0, ttl 64, id 49493, offset 0, flags [DF], proto TCP
> >>>> (6), length 655)
> >>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> >>>> (correct), seq 0:615, ack 1, win 7504, length 615
> >>>> 20:32:08.492487 IP (tos 0x0, ttl 64, id 49494, offset 0, flags [DF], proto TCP
> >>>> (6), length 655)
> >>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> >>>> (correct), seq 0:615, ack 1, win 7504, length 615
> >>>> 20:32:08.493468 IP (tos 0x0, ttl 64, id 49495, offset 0, flags [DF], proto TCP
> >>>> (6), length 655)
> >>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> >>>> (correct), seq 0:615, ack 1, win 7504, length 615
> >>>> 20:32:08.494463 IP (tos 0x0, ttl 64, id 49496, offset 0, flags [DF], proto TCP
> >>>> (6), length 655)
> >>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> >>>> (correct), seq 0:615, ack 1, win 7504, length 615
> >>>> 20:32:08.495463 IP (tos 0x0, ttl 64, id 49497, offset 0, flags [DF], proto TCP
> >>>> (6), length 655)
> >>>> 194.146.153.114.8080 > 172.16.67.243.2512: Flags [P.], cksum 0xce63
> >>>> (correct), seq 0:615, ack 1, win 7504, length 615
> >>>> 20:32:08.496467 IP (tos 0x0, ttl 64, id 49498, offset 0, flags [DF], proto TCP
> >>>> (6), length 655)
> >>>>
> >>>>
> >>>> One more
> >>>> 20:36:13.310718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> >>>> win 7469, length 1440
> >>>> 20:36:13.311725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> >>>> win 7469, length 1440
> >>>> 20:36:13.312729 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> >>>> win 7469, length 1440
> >>>> 20:36:13.313717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> >>>> win 7469, length 1440
> >>>> 20:36:13.314717 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> >>>> win 7469, length 1440
> >>>> 20:36:13.315718 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> >>>> win 7469, length 1440
> >>>> 20:36:13.316725 IP 194.146.153.114.8080 > 172.16.49.30.1319: Flags [.], ack 1,
> >>>> win 7469, length 1440
> >>>>
> >>>> I run multiple times ss
> >>>>
> >>>> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> >>>> timer:(on,,172) uid:101 ino:4772596 sk:c0ce84c0
> >>>> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> >>>> timer:(on,,43) uid:101 ino:4772596 sk:c0ce84c0
> >>>> ESTAB 0 7730 194.146.153.114:8080 172.16.49.30:1319
> >>>> timer:(on,,17) uid:101 ino:4772596 sk:c0ce84c0
> >>>>
> >>>> After i kill squid it will switch socket to FIN-WAIT state and flood will
> >>>> stop.
> >>>>
> >>>> Some sysctl tuning done during boot (maybe related)
> >>>> sysctl -w net.ipv4.tcp_frto=2
> >>>> sysctl -w net.ipv4.tcp_frto_response=2
> >>>>
> >>>> And most probably it is related to keepalive. I have it set on this socket:
> >>>> http_port 8080 transparent tcpkeepalive=30,30,60 http11
> >>>>
> >>>> From manual
> >>>> #<-----> tcpkeepalive[=idle,interval,timeout]
> >>>> #<-----><------><------>Enable TCP keepalive probes of idle connections
> >>>> #<-----><------><------>idle is the initial time before TCP starts probing
> >>>> #<-----><------><------>the connection, interval how often to probe, and
> >>>> #<-----><------><------>timeout the time before giving up.
> >>>>
> >>>> I am not able to reproduce reliably bug, but it is appearing on different
> >>>> cluster pc's randomly for single connection each 5-10 minutes (around 8000
> >>>> established connections to each at moment, 8 pc's in cluster) and dissapearing
> >>>> after 10-50 seconds of flood.
> >>> Damian, can you please take a look. ...It's a bit weird after a very brief
> >>> look (as if RTO would trigger way too often). Maybe its backoff is broken
> >>> now?
> >> ...I meant broken when keepalives are in use.
> >
> > I guess it's that the ICMPs are somehow triggering the
> > tcp_retransmit_timer call in tcp_ipv4 even though they're not supposed
> > to do that until the RTO timeout would have fired. I've no idea why
> > remaining doesn't do what it's supposed to.
> >
>
> Hm.
> Those ICMPs will trigger only, if icsk_backoff and retransmits is non-zero.
> If that's because of a retransmission (which was thought to be), then
> packets_out is non-zero and tcp_probe_timer will return before sending anything.
> Correct me, if I'm wrong here.
> I'll try to think of a case, where those are non-zero with no packets_out.
...I thought that myself too but after some thinking I concluded that
zero packets_out alone would not end up into a loop. ...As the when field
would then get set to a rather valid value on the first (bogus)
transmission of the not yet sent segment, so no loop for the next ICMP
anymore because there should then be plenty of time remaining. I couldn't
immediately determine whether that packets_out == 0 could occur (I suppose
we need to think that through but I'm a bit skeptic that it is the reason
here).
Another alternative to cause this is that icsk_rto become very small for
some reason.
--
i.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2009-12-10 10:24 ` Ilpo Järvinen
@ 2009-12-26 14:54 ` Denys Fedoryshchenko
0 siblings, 0 replies; 15+ messages in thread
From: Denys Fedoryshchenko @ 2009-12-26 14:54 UTC (permalink / raw)
To: Ilpo Järvinen, netdev
>
> ...I thought that myself too but after some thinking I concluded that
> zero packets_out alone would not end up into a loop. ...As the when field
> would then get set to a rather valid value on the first (bogus)
> transmission of the not yet sent segment, so no loop for the next ICMP
> anymore because there should then be plenty of time remaining. I couldn't
> immediately determine whether that packets_out == 0 could occur (I suppose
> we need to think that through but I'm a bit skeptic that it is the reason
> here).
>
> Another alternative to cause this is that icsk_rto become very small for
> some reason.
>
Is there anything i can do?
2.6.32.2 have same issue, and actually hosts doing DDoS for my network. It is
local network with limited capacity and i can manage it, but i imagine if real
world network will have such issue...
Is there anything i can help to debug this?
I try to disable frto,
to put keepalive to default value (2 hours) - issue triggered much earlier
after program restart
tried to disable also timestamps.
All hosts have similar hardware, but not completely same.
r8169, Intel motherboards, Dual core processors(E5300), nothing unusual.
Clocksource tsc
Nothing helps to workaround this bug. And weird thing, why it does ignore ICMP
unreachable?
It seems keeps 10400 bytes in buffer and trying to send them non-stop.
tcp 0 10400 194.146.153.114:8080 172.16.120.230:49435
ESTABLISHED2078/squid
Proxy-16 ~ # ss -et|grep 120.230
ESTAB 0 0 194.146.153.114:http-alt 172.16.16.120:2307
uid:101 ino:97182030 sk:d884e3c0
ESTAB 0 10400 194.146.153.114:http-alt 172.16.120.230:49435
timer:(on,,207) uid:101 ino:97063205 sk:dcdf9c80
Proxy-16 ~ # ss -et|grep 120.230
ESTAB 0 0 194.146.153.114:http-alt 172.16.16.120:2307
uid:101 ino:97182030 sk:d884e3c0
ESTAB 0 10400 194.146.153.114:http-alt 172.16.120.230:49435
timer:(on,,88) uid:101 ino:97063205 sk:dcdf9c80
Proxy-16 ~ # ss -et|grep 120.230
ESTAB 0 0 194.146.153.114:http-alt 172.16.16.120:2307
uid:101 ino:97182030 sk:d884e3c0
ESTAB 0 10400 194.146.153.114:http-alt 172.16.120.230:49435
timer:(on,,113) uid:101 ino:97063205 sk:dcdf9c80
Proxy-16 ~ # ss -aet|grep 120.230
ESTAB 0 10400 194.146.153.114:http-alt 172.16.120.230:49435
timer:(on,,7) uid:101 ino:97063205 sk:dcdf9c80
Proxy-16 ~ # ss -aet|grep 120.230
ESTAB 0 10400 194.146.153.114:http-alt 172.16.120.230:49435
timer:(on,,3) uid:101 ino:97063205 sk:dcdf9c80
Proxy-16 ~ # ss -aet|grep 120.230
ESTAB 0 10400 194.146.153.114:http-alt 172.16.120.230:49435
timer:(on,,9) uid:101 ino:97063205 sk:dcdf9c80
Proxy-16 ~ # ss -aet|grep 120.230
ESTAB 0 10400 194.146.153.114:http-alt 172.16.120.230:49435
timer:(on,,221) uid:101 ino:97063205 sk:dcdf9c80
16:39:43.167575 IP (tos 0x0, ttl 64, id 33482, offset 0, flags [DF], proto TCP
(6), length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], cksum 0xe340
(correct), seq 0:1179, ack 1, win 118, length 1179
16:39:43.168580 IP (tos 0x0, ttl 64, id 33483, offset 0, flags [DF], proto TCP
(6), length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], cksum 0xe340
(correct), seq 0:1179, ack 1, win 118, length 1179
16:39:43.169571 IP (tos 0x0, ttl 64, id 33484, offset 0, flags [DF], proto TCP
(6), length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], cksum 0xe340
(correct), seq 0:1179, ack 1, win 118, length 1179
Proxy-16 /config # tcpdump -ni eth0 src host 172.16.120.230 -vvv -s 1500
tcpdump: WARNING:
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 1500
bytes
16:41:54.774385 IP (tos 0xc0, ttl 59, id 31922, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 31545, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq
3520354182:3520355361, ack 598087346, win 118, length 1179
16:41:54.774509 IP (tos 0xc0, ttl 59, id 31923, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 31634, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq 0:1179, ack
1, win 118, length 1179
16:41:54.774389 IP (tos 0xc0, ttl 59, id 31924, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 31732, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq 0:1179, ack
1, win 118, length 1179
16:41:57.741989 IP (tos 0xc0, ttl 59, id 31925, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 34579, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq 0:1179, ack
1, win 118, length 1179
16:41:57.742169 IP (tos 0xc0, ttl 59, id 31926, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 34689, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq 0:1179, ack
1, win 118, length 1179
16:41:57.742174 IP (tos 0xc0, ttl 59, id 31927, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 34723, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq 0:1179, ack
1, win 118, length 1179
16:42:00.748848 IP (tos 0xc0, ttl 59, id 31928, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 37556, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq 0:1179, ack
1, win 118, length 1179
16:42:00.748856 IP (tos 0xc0, ttl 59, id 31929, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 37597, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq 0:1179, ack
1, win 118, length 1179
16:42:00.759461 IP (tos 0xc0, ttl 59, id 31930, offset 0, flags [none], proto
ICMP (1), length 576)
172.16.120.230 > 194.146.153.114: ICMP host 172.16.120.230 unreachable,
length 556
IP (tos 0x0, ttl 58, id 37715, offset 0, flags [DF], proto TCP (6),
length 1219)
194.146.153.114.8080 > 172.16.120.230.49435: Flags [P.], seq 0:1179, ack
1, win 118, length 1179
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
@ 2009-12-26 15:03 Denys Fedoryshchenko
2009-12-26 19:24 ` Ilpo Järvinen
2010-01-11 13:02 ` Ilpo Järvinen
0 siblings, 2 replies; 15+ messages in thread
From: Denys Fedoryshchenko @ 2009-12-26 15:03 UTC (permalink / raw)
To: Ilpo Järvinen, netdev
Few more dumps. I notice:
1)Ack always equal 1
2)It is usually first segment of data sent (?)
Maybe some value not initialised properly?
17:03:50.406118 IP (tos 0x0, ttl 64, id 57958, offset 0, flags [DF], proto TCP
(6), length 1492)
194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
win 7479, length 1452
17:03:50.407413 IP (tos 0x0, ttl 64, id 57959, offset 0, flags [DF], proto TCP
(6), length 1492)
194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
win 7479, length 1452
17:03:50.408516 IP (tos 0x0, ttl 64, id 57960, offset 0, flags [DF], proto TCP
(6), length 1492)
194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
win 7479, length 1452
17:03:50.409553 IP (tos 0x0, ttl 64, id 57961, offset 0, flags [DF], proto TCP
(6), length 1492)
194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
win 7479, length 1452
17:03:50.410424 IP (tos 0x0, ttl 64, id 57962, offset 0, flags [DF], proto TCP
(6), length 1492)
194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
win 7479, length 1452
17:04:39.801149 IP (tos 0x0, ttl 64, id 19431, offset 0, flags [DF], proto TCP
(6), length 517)
194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
(correct), seq 0:477, ack 1, win 8730, length 477
17:04:39.802538 IP (tos 0x0, ttl 64, id 19432, offset 0, flags [DF], proto TCP
(6), length 517)
194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
(correct), seq 0:477, ack 1, win 8730, length 477
17:04:39.803438 IP (tos 0x0, ttl 64, id 19433, offset 0, flags [DF], proto TCP
(6), length 517)
194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
(correct), seq 0:477, ack 1, win 8730, length 477
17:04:39.804251 IP (tos 0x0, ttl 64, id 19434, offset 0, flags [DF], proto TCP
(6), length 517)
194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
(correct), seq 0:477, ack 1, win 8730, length 477
17:04:39.805050 IP (tos 0x0, ttl 64, id 19435, offset 0, flags [DF], proto TCP
(6), length 517)
194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
(correct), seq 0:477, ack 1, win 8730, length 477
17:06:22.123862 IP (tos 0x0, ttl 64, id 25912, offset 0, flags [DF], proto TCP
(6), length 1492)
194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
win 108, length 1452
17:06:22.124440 IP (tos 0x0, ttl 64, id 25913, offset 0, flags [DF], proto TCP
(6), length 1492)
194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
win 108, length 1452
17:06:22.125600 IP (tos 0x0, ttl 64, id 25914, offset 0, flags [DF], proto TCP
(6), length 1492)
194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
win 108, length 1452
^C17:06:22.126243 IP (tos 0x0, ttl 64, id 25915, offset 0, flags [DF], proto
TCP (6), length 1492)
194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
win 108, length 1452
17:06:43.404279 IP (tos 0x0, ttl 64, id 10279, offset 0, flags [DF], proto TCP
(6), length 768)
194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
(correct), seq 0:728, ack 1, win 9816, length 728
17:06:43.405819 IP (tos 0x0, ttl 64, id 10281, offset 0, flags [DF], proto TCP
(6), length 768)
194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
(correct), seq 0:728, ack 1, win 9816, length 728
17:06:43.406670 IP (tos 0x0, ttl 64, id 10282, offset 0, flags [DF], proto TCP
(6), length 768)
194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
(correct), seq 0:728, ack 1, win 9816, length 728
17:06:43.407821 IP (tos 0x0, ttl 64, id 10283, offset 0, flags [DF], proto TCP
(6), length 768)
194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
(correct), seq 0:728, ack 1, win 9816, length 728
17:07:09.933303 IP (tos 0x0, ttl 64, id 41731, offset 0, flags [DF], proto TCP
(6), length 555)
194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
(correct), seq 0:515, ack 1, win 6432, length 515
17:07:09.934305 IP (tos 0x0, ttl 64, id 41732, offset 0, flags [DF], proto TCP
(6), length 555)
194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
(correct), seq 0:515, ack 1, win 6432, length 515
17:07:09.935076 IP (tos 0x0, ttl 64, id 41733, offset 0, flags [DF], proto TCP
(6), length 555)
194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
(correct), seq 0:515, ack 1, win 6432, length 515
17:07:09.935887 IP (tos 0x0, ttl 64, id 41734, offset 0, flags [DF], proto TCP
(6), length 555)
194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
(correct), seq 0:515, ack 1, win 6432, length 515
17:07:09.937096 IP (tos 0x0, ttl 64, id 41735, offset 0, flags [DF], proto TCP
(6), length 555)
194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
(correct), seq 0:515, ack 1, win 6432, length 515
17:07:09.938083 IP (tos 0x0, ttl 64, id 41736, offset 0, flags [DF], proto TCP
(6), length 555)
194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
(correct), seq 0:515, ack 1, win 6432, length 515
17:09:21.672761 IP (tos 0x0, ttl 64, id 48515, offset 0, flags [DF], proto TCP
(6), length 412)
194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
(correct), seq 0:372, ack 1, win 181, length 372
17:09:21.673756 IP (tos 0x0, ttl 64, id 48516, offset 0, flags [DF], proto TCP
(6), length 412)
194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
(correct), seq 0:372, ack 1, win 181, length 372
17:09:21.674574 IP (tos 0x0, ttl 64, id 48517, offset 0, flags [DF], proto TCP
(6), length 412)
194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
(correct), seq 0:372, ack 1, win 181, length 372
17:09:21.675440 IP (tos 0x0, ttl 64, id 48518, offset 0, flags [DF], proto TCP
(6), length 412)
194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
(correct), seq 0:372, ack 1, win 181, length 372
17:09:21.676625 IP (tos 0x0, ttl 64, id 48519, offset 0, flags [DF], proto TCP
(6), length 412)
194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
(correct), seq 0:372, ack 1, win 181, length 372
17:09:21.678963 IP (tos 0x0, ttl 64, id 48521, offset 0, flags [DF], proto TCP
(6), length 412)
194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
(correct), seq 0:372, ack 1, win 181, length 372
17:11:12.032679 IP (tos 0x0, ttl 64, id 39699, offset 0, flags [DF], proto TCP
(6), length 552)
194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
(correct), seq 0:512, ack 1, win 6432, length 512
17:11:12.033882 IP (tos 0x0, ttl 64, id 39700, offset 0, flags [DF], proto TCP
(6), length 552)
194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
(correct), seq 0:512, ack 1, win 6432, length 512
17:11:12.034835 IP (tos 0x0, ttl 64, id 39701, offset 0, flags [DF], proto TCP
(6), length 552)
194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
(correct), seq 0:512, ack 1, win 6432, length 512
17:11:12.035720 IP (tos 0x0, ttl 64, id 39702, offset 0, flags [DF], proto TCP
(6), length 552)
194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
(correct), seq 0:512, ack 1, win 6432, length 512
^ permalink raw reply [flat|nested] 15+ messages in thread* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2009-12-26 15:03 Denys Fedoryshchenko
@ 2009-12-26 19:24 ` Ilpo Järvinen
2010-01-11 13:02 ` Ilpo Järvinen
1 sibling, 0 replies; 15+ messages in thread
From: Ilpo Järvinen @ 2009-12-26 19:24 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Netdev
On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
> Few more dumps. I notice:
> 1)Ack always equal 1
> 2)It is usually first segment of data sent (?)
Is it that you take the tcpdump right from the beginning? Otherwise
tcpdump will get the base sequence numbers from the first segment which
might be in the middle of the flow already.
> Maybe some value not initialised properly?
>
>
> 17:03:50.406118 IP (tos 0x0, ttl 64, id 57958, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
> 17:03:50.407413 IP (tos 0x0, ttl 64, id 57959, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
> 17:03:50.408516 IP (tos 0x0, ttl 64, id 57960, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
> 17:03:50.409553 IP (tos 0x0, ttl 64, id 57961, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
> 17:03:50.410424 IP (tos 0x0, ttl 64, id 57962, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
>
>
>
> 17:04:39.801149 IP (tos 0x0, ttl 64, id 19431, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
> 17:04:39.802538 IP (tos 0x0, ttl 64, id 19432, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
> 17:04:39.803438 IP (tos 0x0, ttl 64, id 19433, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
> 17:04:39.804251 IP (tos 0x0, ttl 64, id 19434, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
> 17:04:39.805050 IP (tos 0x0, ttl 64, id 19435, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
>
> 17:06:22.123862 IP (tos 0x0, ttl 64, id 25912, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
> win 108, length 1452
> 17:06:22.124440 IP (tos 0x0, ttl 64, id 25913, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
> win 108, length 1452
> 17:06:22.125600 IP (tos 0x0, ttl 64, id 25914, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
> win 108, length 1452
> ^C17:06:22.126243 IP (tos 0x0, ttl 64, id 25915, offset 0, flags [DF], proto
> TCP (6), length 1492)
> 194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
> win 108, length 1452
>
>
>
> 17:06:43.404279 IP (tos 0x0, ttl 64, id 10279, offset 0, flags [DF], proto TCP
> (6), length 768)
> 194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
> (correct), seq 0:728, ack 1, win 9816, length 728
> 17:06:43.405819 IP (tos 0x0, ttl 64, id 10281, offset 0, flags [DF], proto TCP
> (6), length 768)
> 194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
> (correct), seq 0:728, ack 1, win 9816, length 728
> 17:06:43.406670 IP (tos 0x0, ttl 64, id 10282, offset 0, flags [DF], proto TCP
> (6), length 768)
> 194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
> (correct), seq 0:728, ack 1, win 9816, length 728
> 17:06:43.407821 IP (tos 0x0, ttl 64, id 10283, offset 0, flags [DF], proto TCP
> (6), length 768)
> 194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
> (correct), seq 0:728, ack 1, win 9816, length 728
>
>
> 17:07:09.933303 IP (tos 0x0, ttl 64, id 41731, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.934305 IP (tos 0x0, ttl 64, id 41732, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.935076 IP (tos 0x0, ttl 64, id 41733, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.935887 IP (tos 0x0, ttl 64, id 41734, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.937096 IP (tos 0x0, ttl 64, id 41735, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.938083 IP (tos 0x0, ttl 64, id 41736, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
>
> 17:09:21.672761 IP (tos 0x0, ttl 64, id 48515, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.673756 IP (tos 0x0, ttl 64, id 48516, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.674574 IP (tos 0x0, ttl 64, id 48517, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.675440 IP (tos 0x0, ttl 64, id 48518, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.676625 IP (tos 0x0, ttl 64, id 48519, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.678963 IP (tos 0x0, ttl 64, id 48521, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
>
> 17:11:12.032679 IP (tos 0x0, ttl 64, id 39699, offset 0, flags [DF], proto TCP
> (6), length 552)
> 194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
> (correct), seq 0:512, ack 1, win 6432, length 512
> 17:11:12.033882 IP (tos 0x0, ttl 64, id 39700, offset 0, flags [DF], proto TCP
> (6), length 552)
> 194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
> (correct), seq 0:512, ack 1, win 6432, length 512
> 17:11:12.034835 IP (tos 0x0, ttl 64, id 39701, offset 0, flags [DF], proto TCP
> (6), length 552)
> 194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
> (correct), seq 0:512, ack 1, win 6432, length 512
> 17:11:12.035720 IP (tos 0x0, ttl 64, id 39702, offset 0, flags [DF], proto TCP
> (6), length 552)
> 194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
> (correct), seq 0:512, ack 1, win 6432, length 512
>
...I'll try to think this more on next week.
--
i.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2009-12-26 15:03 Denys Fedoryshchenko
2009-12-26 19:24 ` Ilpo Järvinen
@ 2010-01-11 13:02 ` Ilpo Järvinen
2010-01-16 14:12 ` Denys Fedoryshchenko
1 sibling, 1 reply; 15+ messages in thread
From: Ilpo Järvinen @ 2010-01-11 13:02 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Netdev
On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
> Few more dumps. I notice:
> 1)Ack always equal 1
> 2)It is usually first segment of data sent (?)
>
> Maybe some value not initialised properly?
>
>
> 17:03:50.406118 IP (tos 0x0, ttl 64, id 57958, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
> 17:03:50.407413 IP (tos 0x0, ttl 64, id 57959, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
> 17:03:50.408516 IP (tos 0x0, ttl 64, id 57960, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
> 17:03:50.409553 IP (tos 0x0, ttl 64, id 57961, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
> 17:03:50.410424 IP (tos 0x0, ttl 64, id 57962, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.199.39.1472: Flags [.], seq 0:1452, ack 1,
> win 7479, length 1452
>
>
>
> 17:04:39.801149 IP (tos 0x0, ttl 64, id 19431, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
> 17:04:39.802538 IP (tos 0x0, ttl 64, id 19432, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
> 17:04:39.803438 IP (tos 0x0, ttl 64, id 19433, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
> 17:04:39.804251 IP (tos 0x0, ttl 64, id 19434, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
> 17:04:39.805050 IP (tos 0x0, ttl 64, id 19435, offset 0, flags [DF], proto TCP
> (6), length 517)
> 194.146.153.114.8080 > 172.16.107.14.1405: Flags [P.], cksum 0x51c6
> (correct), seq 0:477, ack 1, win 8730, length 477
>
> 17:06:22.123862 IP (tos 0x0, ttl 64, id 25912, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
> win 108, length 1452
> 17:06:22.124440 IP (tos 0x0, ttl 64, id 25913, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
> win 108, length 1452
> 17:06:22.125600 IP (tos 0x0, ttl 64, id 25914, offset 0, flags [DF], proto TCP
> (6), length 1492)
> 194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
> win 108, length 1452
> ^C17:06:22.126243 IP (tos 0x0, ttl 64, id 25915, offset 0, flags [DF], proto
> TCP (6), length 1492)
> 194.146.153.114.8080 > 172.16.180.148.50101: Flags [.], seq 0:1452, ack 1,
> win 108, length 1452
>
>
>
> 17:06:43.404279 IP (tos 0x0, ttl 64, id 10279, offset 0, flags [DF], proto TCP
> (6), length 768)
> 194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
> (correct), seq 0:728, ack 1, win 9816, length 728
> 17:06:43.405819 IP (tos 0x0, ttl 64, id 10281, offset 0, flags [DF], proto TCP
> (6), length 768)
> 194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
> (correct), seq 0:728, ack 1, win 9816, length 728
> 17:06:43.406670 IP (tos 0x0, ttl 64, id 10282, offset 0, flags [DF], proto TCP
> (6), length 768)
> 194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
> (correct), seq 0:728, ack 1, win 9816, length 728
> 17:06:43.407821 IP (tos 0x0, ttl 64, id 10283, offset 0, flags [DF], proto TCP
> (6), length 768)
> 194.146.153.114.8080 > 172.16.199.151.49404: Flags [FP.], cksum 0x4ac3
> (correct), seq 0:728, ack 1, win 9816, length 728
>
>
> 17:07:09.933303 IP (tos 0x0, ttl 64, id 41731, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.934305 IP (tos 0x0, ttl 64, id 41732, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.935076 IP (tos 0x0, ttl 64, id 41733, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.935887 IP (tos 0x0, ttl 64, id 41734, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.937096 IP (tos 0x0, ttl 64, id 41735, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
> 17:07:09.938083 IP (tos 0x0, ttl 64, id 41736, offset 0, flags [DF], proto TCP
> (6), length 555)
> 194.146.153.114.8080 > 172.16.175.130.1692: Flags [P.], cksum 0x7d98
> (correct), seq 0:515, ack 1, win 6432, length 515
>
> 17:09:21.672761 IP (tos 0x0, ttl 64, id 48515, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.673756 IP (tos 0x0, ttl 64, id 48516, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.674574 IP (tos 0x0, ttl 64, id 48517, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.675440 IP (tos 0x0, ttl 64, id 48518, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.676625 IP (tos 0x0, ttl 64, id 48519, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
> 17:09:21.678963 IP (tos 0x0, ttl 64, id 48521, offset 0, flags [DF], proto TCP
> (6), length 412)
> 194.146.153.114.8080 > 172.16.163.219.47653: Flags [P.], cksum 0x584c
> (correct), seq 0:372, ack 1, win 181, length 372
>
> 17:11:12.032679 IP (tos 0x0, ttl 64, id 39699, offset 0, flags [DF], proto TCP
> (6), length 552)
> 194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
> (correct), seq 0:512, ack 1, win 6432, length 512
> 17:11:12.033882 IP (tos 0x0, ttl 64, id 39700, offset 0, flags [DF], proto TCP
> (6), length 552)
> 194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
> (correct), seq 0:512, ack 1, win 6432, length 512
> 17:11:12.034835 IP (tos 0x0, ttl 64, id 39701, offset 0, flags [DF], proto TCP
> (6), length 552)
> 194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
> (correct), seq 0:512, ack 1, win 6432, length 512
> 17:11:12.035720 IP (tos 0x0, ttl 64, id 39702, offset 0, flags [DF], proto TCP
> (6), length 552)
> 194.146.153.114.8080 > 172.16.15.13.63145: Flags [P.], cksum 0x1559
> (correct), seq 0:512, ack 1, win 6432, length 512
>
Can you see if the RTO lower bound is violated (I added some printing of
vars there too already now if it turns out to be something):
diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
index 65b8ebf..d84469f 100644
--- a/net/ipv4/tcp_ipv4.c
+++ b/net/ipv4/tcp_ipv4.c
@@ -327,6 +327,22 @@ static void do_pmtu_discovery(struct sock *sk, struct iphdr *iph, u32 mtu)
* is probably better.
*
*/
+static int prints = 0;
+
+static void tcp_debug_rto(struct sock *sk, struct sk_buff *skb, u32 remaining, int locked)
+{
+ struct inet_connection_sock *icsk = inet_csk(sk);
+ struct tcp_sock *tp = tcp_sk(sk);
+
+ if (prints++ < 1000) {
+ printk("rto: %u (%u >> 3 + %u, %u) time: %u sent: %u pen: %u %lu rem: %u %s\n",
+ icsk->icsk_rto, tp->srtt, tp->rttvar,
+ (u32)icsk->icsk_backoff,
+ tcp_time_stamp, TCP_SKB_CB(skb)->when,
+ (u32)icsk->icsk_pending, icsk->icsk_timeout, remaining,
+ locked ? "locked" : "");
+ }
+}
void tcp_v4_err(struct sk_buff *icmp_skb, u32 info)
{
@@ -409,6 +425,11 @@ void tcp_v4_err(struct sk_buff *icmp_skb, u32 info)
inet_csk(sk)->icsk_rto = __tcp_set_rto(tp) <<
icsk->icsk_backoff;
tcp_bound_rto(sk);
+ if (icsk->icsk_rto < TCP_RTO_MIN) {
+ if (net_ratelimit())
+ printk("lower bound violation: %u\n", icsk->icsk_rto);
+ icsk->icsk_rto = TCP_RTO_MIN;
+ }
skb = tcp_write_queue_head(sk);
BUG_ON(!skb);
@@ -417,14 +438,17 @@ void tcp_v4_err(struct sk_buff *icmp_skb, u32 info)
tcp_time_stamp - TCP_SKB_CB(skb)->when);
if (remaining) {
+ tcp_debug_rto(sk, skb, remaining, 0);
inet_csk_reset_xmit_timer(sk, ICSK_TIME_RETRANS,
remaining, TCP_RTO_MAX);
} else if (sock_owned_by_user(sk)) {
+ tcp_debug_rto(sk, skb, remaining, 1);
/* RTO revert clocked out retransmission,
* but socket is locked. Will defer. */
inet_csk_reset_xmit_timer(sk, ICSK_TIME_RETRANS,
HZ/20, TCP_RTO_MAX);
} else {
+ tcp_debug_rto(sk, skb, remaining, 0);
/* RTO revert clocked out retransmission.
* Will retransmit now */
tcp_retransmit_timer(sk);
^ permalink raw reply related [flat|nested] 15+ messages in thread* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2010-01-11 13:02 ` Ilpo Järvinen
@ 2010-01-16 14:12 ` Denys Fedoryshchenko
2010-01-19 9:10 ` Damian Lukowski
0 siblings, 1 reply; 15+ messages in thread
From: Denys Fedoryshchenko @ 2010-01-16 14:12 UTC (permalink / raw)
To: Ilpo Järvinen, netdev
On Monday 11 January 2010 15:02:34 you wrote:
> On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
> > Few more dumps. I notice:
> > 1)Ack always equal 1
> > 2)It is usually first segment of data sent (?)
> >
> > Maybe some value not initialised properly?
> >
> >
> Can you see if the RTO lower bound is violated (I added some printing of
> vars there too already now if it turns out to be something):
>
> diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
> index 65b8ebf..d84469f 100644
> --- a/net/ipv4/tcp_ipv4.c
> +++ b/net/ipv4/tcp_ipv4.c
> @@ -327,6 +327,22 @@ static void do_pmtu_discovery(struct sock *sk, struct
Hi, i'm very sorry for delay. Just having problem with Lebanese ISP's (u pay
20k for 20mbit, u get 20% packetloss at peak time, and they say it is normal).
I did test, here is some things from dmesg
[ 396.496765] lower bound violation: 0
[ 396.496833] rto: 200 (0 >> 3 + 0, 4) time: 96496 sent: 96496 pen: 1 96696
rem: 200
[ 399.442640] lower bound violation: 0
[ 399.442721] rto: 200 (0 >> 3 + 0, 16) time: 99442 sent: 99421 pen: 1 102621
rem: 179
[ 399.444802] lower bound violation: 0
[ 399.444881] rto: 200 (0 >> 3 + 0, 10) time: 99444 sent: 99233 pen: 1 102433
rem: 0
[ 399.446444] lower bound violation: 0
[ 399.446521] rto: 200 (0 >> 3 + 0, 15) time: 99446 sent: 99421 pen: 1 99621
rem: 175
[ 399.539751] lower bound violation: 0
[ 399.539832] rto: 200 (0 >> 3 + 0, 7) time: 99539 sent: 99496 pen: 1 102696
rem: 157
[ 399.539964] rto: 200 (0 >> 3 + 0, 6) time: 99539 sent: 99496 pen: 1 99696
rem: 157
[ 399.540650] rto: 200 (0 >> 3 + 0, 5) time: 99540 sent: 99496 pen: 1 99696
rem: 156
[ 402.445674] __ratelimit: 2 callbacks suppressed
[ 402.445756] lower bound violation: 0
[ 402.445833] rto: 200 (0 >> 3 + 0, 18) time: 102445 sent: 102421 pen: 1
105621 rem: 176
[ 402.445958] lower bound violation: 0
[ 402.446026] rto: 200 (0 >> 3 + 0, 13) time: 102445 sent: 102244 pen: 1
105444 rem: 0
[ 402.446150] lower bound violation: 0
[ 402.446217] rto: 200 (0 >> 3 + 0, 17) time: 102446 sent: 102421 pen: 1
102621 rem: 175
[ 402.742463] lower bound violation: 0
[ 402.742544] rto: 200 (0 >> 3 + 0, 8) time: 102742 sent: 102496 pen: 1
105696 rem: 0
[ 402.743567] lower bound violation: 0
[ 402.744361] rto: 200 (0 >> 3 + 0, 8) time: 102744 sent: 102742 pen: 1
103142 rem: 198
[ 402.744478] lower bound violation: 0
[ 402.744545] rto: 200 (0 >> 3 + 0, 7) time: 102744 sent: 102742 pen: 1
102942 rem: 198
[ 405.446861] lower bound violation: 0
[ 405.446943] rto: 200 (0 >> 3 + 0, 20) time: 105446 sent: 105421 pen: 1
108621 rem: 175
[ 405.447075] lower bound violation: 0
[ 405.447142] rto: 200 (0 >> 3 + 0, 16) time: 105446 sent: 105246 pen: 1
108446 rem: 0
[ 405.447265] lower bound violation: 0
[ 405.447332] rto: 200 (0 >> 3 + 0, 19) time: 105446 sent: 105421 pen: 1
105621 rem: 175
[ 405.759226] lower bound violation: 0
[ 405.759307] rto: 200 (0 >> 3 + 0, 10) time: 105759 sent: 105742 pen: 1
108942 rem: 183
[ 405.763529] rto: 200 (0 >> 3 + 0, 9) time: 105763 sent: 105742 pen: 1
105942 rem: 179
[ 405.764344] rto: 200 (0 >> 3 + 0, 8) time: 105764 sent: 105742 pen: 1
105942 rem: 178
[ 408.450964] __ratelimit: 2 callbacks suppressed
[ 408.451045] lower bound violation: 0
[ 408.451121] rto: 200 (0 >> 3 + 0, 22) time: 108450 sent: 108421 pen: 1
111621 rem: 171
[ 408.451246] lower bound violation: 0
[ 408.451314] rto: 200 (0 >> 3 + 0, 19) time: 108450 sent: 108246 pen: 1
111446 rem: 0
[ 408.451437] lower bound violation: 0
[ 408.451504] rto: 200 (0 >> 3 + 0, 21) time: 108450 sent: 108421 pen: 1
108621 rem: 171
[ 408.792229] lower bound violation: 0
[ 408.792307] rto: 200 (0 >> 3 + 0, 11) time: 108792 sent: 108742 pen: 1
111942 rem: 150
[ 408.792821] lower bound violation: 0
[ 408.792897] rto: 200 (0 >> 3 + 0, 10) time: 108792 sent: 108742 pen: 1
108942 rem: 150
[ 408.793033] lower bound violation: 0
[ 408.793109] rto: 200 (0 >> 3 + 0, 9) time: 108793 sent: 108742 pen: 1
108943 rem: 149
[ 411.478006] lower bound violation: 0
[ 411.478088] rto: 200 (0 >> 3 + 0, 24) time: 111478 sent: 111421 pen: 1
114621 rem: 143
[ 411.478220] lower bound violation: 0
[ 411.478287] rto: 200 (0 >> 3 + 0, 22) time: 111478 sent: 111250 pen: 1
114450 rem: 0
[ 411.478411] lower bound violation: 0
[ 411.478478] rto: 200 (0 >> 3 + 0, 23) time: 111478 sent: 111421 pen: 1
111621 rem: 143
[ 411.804382] lower bound violation: 0
[ 411.804464] rto: 200 (0 >> 3 + 0, 12) time: 111804 sent: 111742 pen: 1
114942 rem: 138
[ 411.804598] rto: 200 (0 >> 3 + 0, 11) time: 111804 sent: 111742 pen: 1
111942 rem: 138
[ 414.498996] __ratelimit: 1 callbacks suppressed
[ 414.499080] lower bound violation: 0
[ 414.499160] rto: 200 (0 >> 3 + 0, 26) time: 114498 sent: 114421 pen: 1
117621 rem: 123
[ 414.513129] lower bound violation: 0
[ 414.513207] rto: 200 (0 >> 3 + 0, 25) time: 114513 sent: 114278 pen: 1
117478 rem: 0
[ 414.513344] lower bound violation: 0
[ 414.513412] rto: 200 (0 >> 3 + 0, 25) time: 114513 sent: 114421 pen: 1
114621 rem: 108
[ 414.784717] lower bound violation: 0
[ 414.784799] rto: 200 (0 >> 3 + 0, 14) time: 114784 sent: 114742 pen: 1
117942 rem: 158
[ 414.786072] lower bound violation: 0
[ 414.786152] rto: 200 (0 >> 3 + 0, 13) time: 114786 sent: 114742 pen: 1
114942 rem: 156
[ 417.515995] lower bound violation: 0
[ 417.516077] rto: 200 (0 >> 3 + 0, 28) time: 117516 sent: 117421 pen: 1
120621 rem: 105
[ 417.516213] lower bound violation: 0
[ 417.516289] rto: 200 (0 >> 3 + 0, 28) time: 117516 sent: 117313 pen: 1
120513 rem: 0
[ 417.516413] lower bound violation: 0
[ 417.516481] rto: 200 (0 >> 3 + 0, 27) time: 117516 sent: 117421 pen: 1
117621 rem: 105
[ 417.803533] lower bound violation: 0
[ 417.803615] rto: 200 (0 >> 3 + 0, 16) time: 117803 sent: 117742 pen: 1
120942 rem: 139
[ 417.803745] lower bound violation: 0
[ 417.803812] rto: 200 (0 >> 3 + 0, 15) time: 117803 sent: 117742 pen: 1
117942 rem: 139
[ 417.803930] rto: 200 (0 >> 3 + 0, 14) time: 117803 sent: 117742 pen: 1
117942 rem: 139
[ 420.556115] __ratelimit: 1 callbacks suppressed
[ 420.556198] lower bound violation: 0
[ 420.556274] rto: 200 (0 >> 3 + 0, 30) time: 120556 sent: 120421 pen: 1
123621 rem: 65
[ 420.556399] lower bound violation: 0
[ 420.556466] rto: 200 (0 >> 3 + 0, 31) time: 120556 sent: 120316 pen: 1
123516 rem: 0
[ 420.556591] lower bound violation: 0
[ 420.556659] rto: 200 (0 >> 3 + 0, 29) time: 120556 sent: 120421 pen: 1
120621 rem: 65
[ 420.965666] lower bound violation: 0
[ 420.965749] rto: 200 (0 >> 3 + 0, 17) time: 120965 sent: 120742 pen: 1
123942 rem: 0
[ 420.967717] lower bound violation: 0
[ 420.967796] rto: 200 (0 >> 3 + 0, 17) time: 120967 sent: 120965 pen: 1
121365 rem: 198
[ 420.972139] lower bound violation: 0
[ 420.972216] rto: 200 (0 >> 3 + 0, 16) time: 120972 sent: 120965 pen: 1
121165 rem: 193
[ 423.564843] lower bound violation: 0
[ 423.564924] rto: 200 (0 >> 3 + 0, 32) time: 123564 sent: 123421 pen: 1
126621 rem: 57
[ 423.565062] lower bound violation: 0
[ 423.565130] rto: 200 (0 >> 3 + 0, 34) time: 123565 sent: 123356 pen: 1
126556 rem: 0
[ 423.565254] lower bound violation: 0
[ 423.565322] rto: 200 (0 >> 3 + 0, 31) time: 123565 sent: 123421 pen: 1
123622 rem: 56
[ 424.001854] lower bound violation: 0
[ 424.001936] rto: 200 (0 >> 3 + 0, 19) time: 124001 sent: 123965 pen: 1
127165 rem: 164
[ 424.005665] rto: 200 (0 >> 3 + 0, 18) time: 124005 sent: 123965 pen: 1
124166 rem: 160
[ 424.007636] rto: 200 (0 >> 3 + 0, 17) time: 124007 sent: 123965 pen: 1
124165 rem: 158
[ 426.580172] __ratelimit: 2 callbacks suppressed
[ 426.580254] lower bound violation: 0
[ 426.580337] rto: 200 (0 >> 3 + 0, 34) time: 126580 sent: 126421 pen: 1
129621 rem: 41
[ 426.580456] lower bound violation: 0
[ 426.580524] rto: 200 (0 >> 3 + 0, 37) time: 126580 sent: 126365 pen: 1
129565 rem: 0
[ 426.580647] lower bound violation: 0
[ 426.580715] rto: 200 (0 >> 3 + 0, 33) time: 126580 sent: 126421 pen: 1
126621 rem: 41
[ 427.210363] lower bound violation: 0
[ 427.210443] rto: 200 (0 >> 3 + 0, 20) time: 127210 sent: 126965 pen: 1
130165 rem: 0
[ 427.210587] lower bound violation: 0
[ 427.210654] rto: 200 (0 >> 3 + 0, 20) time: 127210 sent: 127210 pen: 1
127610 rem: 200
[ 427.210770] lower bound violation: 0
[ 427.210837] rto: 200 (0 >> 3 + 0, 19) time: 127210 sent: 127210 pen: 1
127410 rem: 200
[ 429.586539] lower bound violation: 0
[ 429.586628] rto: 200 (0 >> 3 + 0, 36) time: 129586 sent: 129421 pen: 1
132621 rem: 35
[ 429.588735] lower bound violation: 0
[ 429.588814] rto: 200 (0 >> 3 + 0, 40) time: 129588 sent: 129380 pen: 1
132580 rem: 0
[ 429.589880] lower bound violation: 0
[ 429.589957] rto: 200 (0 >> 3 + 0, 35) time: 129589 sent: 129421 pen: 1
129621 rem: 32
[ 430.231164] lower bound violation: 0
[ 430.231246] rto: 200 (0 >> 3 + 0, 22) time: 130231 sent: 130210 pen: 1
133410 rem: 179
[ 430.253497] rto: 200 (0 >> 3 + 0, 21) time: 130253 sent: 130210 pen: 1
130410 rem: 157
[ 432.600005] __ratelimit: 1 callbacks suppressed
[ 432.600087] lower bound violation: 0
[ 432.600164] rto: 200 (0 >> 3 + 0, 38) time: 132600 sent: 132421 pen: 1
135621 rem: 21
[ 432.601516] lower bound violation: 0
[ 432.601593] rto: 200 (0 >> 3 + 0, 43) time: 132601 sent: 132388 pen: 1
135588 rem: 0
[ 432.601729] lower bound violation: 0
[ 432.601796] rto: 200 (0 >> 3 + 0, 37) time: 132601 sent: 132421 pen: 1
132621 rem: 20
[ 433.292095] lower bound violation: 0
[ 433.292177] rto: 200 (0 >> 3 + 0, 24) time: 133292 sent: 133210 pen: 1
136410 rem: 118
[ 433.292308] lower bound violation: 0
[ 433.292375] rto: 200 (0 >> 3 + 0, 23) time: 133292 sent: 133210 pen: 1
133410 rem: 118
[ 433.292491] lower bound violation: 0
[ 433.292558] rto: 200 (0 >> 3 + 0, 22) time: 133292 sent: 133210 pen: 1
133410 rem: 118
[ 435.624429] lower bound violation: 0
[ 435.624512] rto: 200 (0 >> 3 + 0, 40) time: 135624 sent: 135421 pen: 1
138621 rem: 0
[ 435.624649] lower bound violation: 0
[ 435.624717] rto: 200 (0 >> 3 + 0, 46) time: 135624 sent: 135401 pen: 1
138601 rem: 0
[ 435.625410] lower bound violation: 0
[ 435.625410] rto: 200 (0 >> 3 + 0, 40) time: 135624 sent: 135624 pen: 1
136024 rem: 200
[ 436.455058] lower bound violation: 0
[ 436.455140] rto: 200 (0 >> 3 + 0, 25) time: 136455 sent: 136210 pen: 1
139410 rem: 0
[ 436.455279] rto: 200 (0 >> 3 + 0, 25) time: 136455 sent: 136455 pen: 1
136855 rem: 200
[ 436.455397] rto: 200 (0 >> 3 + 0, 24) time: 136455 sent: 136455 pen: 1
136655 rem: 200
[ 439.507877] __ratelimit: 2 callbacks suppressed
[ 439.507959] lower bound violation: 0
[ 439.508037] rto: 200 (0 >> 3 + 0, 27) time: 139507 sent: 139455 pen: 1
142655 rem: 148
[ 439.508161] lower bound violation: 0
[ 439.508228] rto: 200 (0 >> 3 + 0, 26) time: 139507 sent: 139455 pen: 1
139655 rem: 148
[ 442.507756] lower bound violation: 0
[ 442.507838] rto: 200 (0 >> 3 + 0, 29) time: 142507 sent: 142455 pen: 1
145655 rem: 148
[ 442.507969] lower bound violation: 0
[ 442.508035] rto: 200 (0 >> 3 + 0, 28) time: 142507 sent: 142455 pen: 1
142655 rem: 148
[ 442.508152] lower bound violation: 0
[ 442.508219] rto: 200 (0 >> 3 + 0, 27) time: 142507 sent: 142455 pen: 1
142655 rem: 148
[ 445.498049] lower bound violation: 0
[ 445.498130] rto: 200 (0 >> 3 + 0, 30) time: 145498 sent: 145455 pen: 1
148655 rem: 157
[ 445.499105] lower bound violation: 0
[ 445.499194] rto: 200 (0 >> 3 + 0, 29) time: 145499 sent: 145455 pen: 1
145655 rem: 156
[ 445.501524] lower bound violation: 0
[ 445.501600] rto: 200 (0 >> 3 + 0, 28) time: 145501 sent: 145455 pen: 1
145655 rem: 154
[ 448.678590] lower bound violation: 0
[ 448.678671] rto: 200 (0 >> 3 + 0, 31) time: 148678 sent: 148455 pen: 1
151655 rem: 0
[ 448.678808] lower bound violation: 0
[ 448.678876] rto: 200 (0 >> 3 + 0, 31) time: 148678 sent: 148678 pen: 1
149078 rem: 200
[ 451.716905] lower bound violation: 0
[ 451.716987] rto: 200 (0 >> 3 + 0, 34) time: 151716 sent: 151678 pen: 1
154878 rem: 162
[ 451.763041] lower bound violation: 0
[ 451.763121] rto: 200 (0 >> 3 + 0, 33) time: 151763 sent: 151678 pen: 1
151878 rem: 115
[ 451.763252] lower bound violation: 0
[ 451.763320] rto: 200 (0 >> 3 + 0, 32) time: 151763 sent: 151678 pen: 1
151878 rem: 115
[ 454.732396] lower bound violation: 0
[ 454.732478] rto: 200 (0 >> 3 + 0, 35) time: 154732 sent: 154678 pen: 1
157878 rem: 146
[ 454.736990] lower bound violation: 0
[ 454.737072] rto: 200 (0 >> 3 + 0, 34) time: 154737 sent: 154678 pen: 1
154878 rem: 141
[ 454.738128] lower bound violation: 0
[ 454.738206] rto: 200 (0 >> 3 + 0, 33) time: 154738 sent: 154678 pen: 1
154878 rem: 140
[ 457.894010] lower bound violation: 0
[ 457.894098] rto: 200 (0 >> 3 + 0, 36) time: 157894 sent: 157678 pen: 1
160878 rem: 0
[ 457.913672] lower bound violation: 0
[ 457.913751] rto: 200 (0 >> 3 + 0, 36) time: 157913 sent: 157894 pen: 1
158294 rem: 181
[ 457.913883] lower bound violation: 0
[ 457.913950] rto: 200 (0 >> 3 + 0, 35) time: 157913 sent: 157894 pen: 1
158094 rem: 181
[ 460.932992] lower bound violation: 0
[ 460.933073] rto: 200 (0 >> 3 + 0, 38) time: 160932 sent: 160894 pen: 1
164094 rem: 162
[ 460.933206] lower bound violation: 0
[ 460.933273] rto: 200 (0 >> 3 + 0, 37) time: 160932 sent: 160894 pen: 1
161094 rem: 162
[ 460.933390] lower bound violation: 0
[ 460.933457] rto: 200 (0 >> 3 + 0, 36) time: 160932 sent: 160894 pen: 1
161094 rem: 162
[ 463.928470] lower bound violation: 0
[ 463.928551] rto: 200 (0 >> 3 + 0, 39) time: 163928 sent: 163894 pen: 1
167094 rem: 166
[ 466.953674] lower bound violation: 0
[ 466.953755] rto: 200 (0 >> 3 + 0, 42) time: 166953 sent: 166894 pen: 1
170094 rem: 141
[ 466.953887] lower bound violation: 0
[ 466.953954] rto: 200 (0 >> 3 + 0, 41) time: 166953 sent: 166894 pen: 1
167094 rem: 141
[ 470.112498] lower bound violation: 0
[ 470.112580] rto: 200 (0 >> 3 + 0, 44) time: 170112 sent: 169894 pen: 1
173094 rem: 0
[ 470.127286] lower bound violation: 0
[ 470.127364] rto: 200 (0 >> 3 + 0, 44) time: 170127 sent: 170112 pen: 1
170512 rem: 185
[ 473.167817] lower bound violation: 0
[ 473.167899] rto: 200 (0 >> 3 + 0, 47) time: 173167 sent: 173112 pen: 1
176312 rem: 145
[ 473.168030] lower bound violation: 0
[ 473.168098] rto: 200 (0 >> 3 + 0, 46) time: 173168 sent: 173112 pen: 1
173313 rem: 144
[ 473.169413] lower bound violation: 0
[ 473.169491] rto: 200 (0 >> 3 + 0, 45) time: 173169 sent: 173112 pen: 1
173312 rem: 143
[ 522.630573] lower bound violation: 0
[ 522.630655] rto: 200 (0 >> 3 + 0, 0) time: 222630 sent: 222630 pen: 1
228630 rem: 200
[ 627.844099] lower bound violation: 0
[ 627.844176] rto: 200 (0 >> 3 + 0, 8) time: 327844 sent: 324830 pen: 1
427230 rem: 0
[ 630.848249] lower bound violation: 0
[ 630.848333] rto: 200 (0 >> 3 + 0, 11) time: 330848 sent: 330644 pen: 1
333844 rem: 0
[ 735.859328] lower bound violation: 0
[ 735.859388] rto: 200 (0 >> 3 + 0, 19) time: 435859 sent: 432848 pen: 1
535248 rem: 0
[ 738.864261] lower bound violation: 0
[ 738.864322] rto: 200 (0 >> 3 + 0, 22) time: 438864 sent: 438659 pen: 1
441859 rem: 0
[ 738.865358] lower bound violation: 0
[ 738.865415] rto: 200 (0 >> 3 + 0, 22) time: 438865 sent: 438864 pen: 1
439264 rem: 199
[ 741.864947] lower bound violation: 0
[ 741.865007] rto: 200 (0 >> 3 + 0, 25) time: 441864 sent: 441864 pen: 1
445064 rem: 200
[ 741.867651] lower bound violation: 0
[ 741.867709] rto: 200 (0 >> 3 + 0, 24) time: 441867 sent: 441864 pen: 1
442065 rem: 197
[ 741.867821] lower bound violation: 0
[ 741.867875] rto: 200 (0 >> 3 + 0, 23) time: 441867 sent: 441864 pen: 1
442064 rem: 197
[ 744.874165] lower bound violation: 0
[ 744.874225] rto: 200 (0 >> 3 + 0, 26) time: 444874 sent: 444864 pen: 1
448064 rem: 190
[ 744.874340] lower bound violation: 0
[ 744.874388] rto: 200 (0 >> 3 + 0, 25) time: 444874 sent: 444864 pen: 1
445064 rem: 190
[ 744.874486] lower bound violation: 0
[ 744.874535] rto: 200 (0 >> 3 + 0, 24) time: 444874 sent: 444864 pen: 1
445064 rem: 190
[ 747.874311] lower bound violation: 0
[ 747.874373] rto: 200 (0 >> 3 + 0, 27) time: 447874 sent: 447864 pen: 1
451064 rem: 190
[ 747.874474] lower bound violation: 0
[ 747.874523] rto: 200 (0 >> 3 + 0, 26) time: 447874 sent: 447864 pen: 1
448064 rem: 190
[ 747.874628] lower bound violation: 0
[ 747.874677] rto: 200 (0 >> 3 + 0, 25) time: 447874 sent: 447864 pen: 1
448064 rem: 190
[ 750.870109] lower bound violation: 0
[ 750.870170] rto: 200 (0 >> 3 + 0, 28) time: 450870 sent: 450864 pen: 1
454064 rem: 194
[ 750.870281] lower bound violation: 0
[ 750.870330] rto: 200 (0 >> 3 + 0, 27) time: 450870 sent: 450864 pen: 1
451064 rem: 194
[ 750.870435] lower bound violation: 0
[ 750.870484] rto: 200 (0 >> 3 + 0, 26) time: 450870 sent: 450864 pen: 1
451064 rem: 194
[ 753.882598] lower bound violation: 0
[ 753.882661] rto: 200 (0 >> 3 + 0, 29) time: 453882 sent: 453864 pen: 1
457064 rem: 182
[ 753.882779] lower bound violation: 0
[ 753.882842] rto: 200 (0 >> 3 + 0, 28) time: 453882 sent: 453864 pen: 1
454064 rem: 182
[ 753.882975] lower bound violation: 0
[ 753.883050] rto: 200 (0 >> 3 + 0, 27) time: 453883 sent: 453864 pen: 1
454064 rem: 181
[ 756.874204] lower bound violation: 0
[ 756.874265] rto: 200 (0 >> 3 + 0, 30) time: 456874 sent: 456864 pen: 1
460064 rem: 190
[ 756.874376] lower bound violation: 0
[ 756.874424] rto: 200 (0 >> 3 + 0, 29) time: 456874 sent: 456864 pen: 1
457064 rem: 190
[ 756.874527] lower bound violation: 0
[ 756.874576] rto: 200 (0 >> 3 + 0, 28) time: 456874 sent: 456864 pen: 1
457064 rem: 190
[ 759.891416] lower bound violation: 0
[ 759.891480] rto: 200 (0 >> 3 + 0, 31) time: 459891 sent: 459864 pen: 1
463064 rem: 173
[ 759.891591] lower bound violation: 0
[ 759.891647] rto: 200 (0 >> 3 + 0, 30) time: 459891 sent: 459864 pen: 1
460064 rem: 173
[ 759.891746] lower bound violation: 0
[ 759.892390] rto: 200 (0 >> 3 + 0, 29) time: 459891 sent: 459864 pen: 1
460064 rem: 173
[ 763.066046] lower bound violation: 0
[ 763.066106] rto: 200 (0 >> 3 + 0, 32) time: 463066 sent: 462864 pen: 1
466064 rem: 0
[ 763.066224] lower bound violation: 0
[ 763.066273] rto: 200 (0 >> 3 + 0, 32) time: 463066 sent: 463066 pen: 1
463466 rem: 200
[ 763.066371] lower bound violation: 0
[ 763.066419] rto: 200 (0 >> 3 + 0, 31) time: 463066 sent: 463066 pen: 1
463266 rem: 200
[ 766.065427] lower bound violation: 0
[ 766.065501] rto: 200 (0 >> 3 + 0, 33) time: 466065 sent: 464466 pen: 1
466066 rem: 0
[ 766.069012] lower bound violation: 0
[ 766.069070] rto: 200 (0 >> 3 + 0, 33) time: 466068 sent: 466065 pen: 1
466465 rem: 197
[ 766.069184] lower bound violation: 0
[ 766.069242] rto: 200 (0 >> 3 + 0, 32) time: 466069 sent: 466065 pen: 1
466266 rem: 196
[ 769.077813] lower bound violation: 0
[ 769.077873] rto: 200 (0 >> 3 + 0, 35) time: 469077 sent: 469065 pen: 1
472265 rem: 188
[ 769.077985] lower bound violation: 0
[ 769.078043] rto: 200 (0 >> 3 + 0, 34) time: 469078 sent: 469065 pen: 1
469265 rem: 187
[ 772.078686] lower bound violation: 0
[ 772.078746] rto: 200 (0 >> 3 + 0, 37) time: 472078 sent: 472065 pen: 1
475265 rem: 187
[ 772.078859] lower bound violation: 0
[ 772.078907] rto: 200 (0 >> 3 + 0, 36) time: 472078 sent: 472065 pen: 1
472265 rem: 187
[ 772.079674] lower bound violation: 0
[ 772.079731] rto: 200 (0 >> 3 + 0, 35) time: 472079 sent: 472065 pen: 1
472265 rem: 186
[ 775.269432] lower bound violation: 0
[ 775.269494] rto: 200 (0 >> 3 + 0, 38) time: 475269 sent: 475065 pen: 1
478265 rem: 0
[ 775.270671] lower bound violation: 0
[ 775.270733] rto: 200 (0 >> 3 + 0, 38) time: 475270 sent: 475269 pen: 1
475669 rem: 199
[ 775.270848] lower bound violation: 0
[ 775.270897] rto: 200 (0 >> 3 + 0, 37) time: 475270 sent: 475269 pen: 1
475469 rem: 199
[ 778.277343] lower bound violation: 0
[ 778.277404] rto: 200 (0 >> 3 + 0, 40) time: 478277 sent: 478269 pen: 1
481469 rem: 192
[ 778.277536] lower bound violation: 0
[ 778.277602] rto: 200 (0 >> 3 + 0, 39) time: 478277 sent: 478269 pen: 1
478469 rem: 192
[ 778.277722] lower bound violation: 0
[ 778.277778] rto: 200 (0 >> 3 + 0, 38) time: 478277 sent: 478269 pen: 1
478469 rem: 192
[ 781.272677] lower bound violation: 0
[ 781.272737] rto: 200 (0 >> 3 + 0, 41) time: 481272 sent: 481269 pen: 1
484469 rem: 197
[ 781.272850] lower bound violation: 0
[ 781.272898] rto: 200 (0 >> 3 + 0, 40) time: 481272 sent: 481269 pen: 1
481469 rem: 197
[ 784.274886] lower bound violation: 0
[ 784.274946] rto: 200 (0 >> 3 + 0, 43) time: 484274 sent: 484269 pen: 1
487469 rem: 195
[ 784.275064] lower bound violation: 0
[ 784.275112] rto: 200 (0 >> 3 + 0, 42) time: 484275 sent: 484269 pen: 1
484470 rem: 194
[ 784.275212] lower bound violation: 0
[ 784.275260] rto: 200 (0 >> 3 + 0, 41) time: 484275 sent: 484269 pen: 1
484469 rem: 194
[ 787.274753] lower bound violation: 0
[ 787.274814] rto: 200 (0 >> 3 + 0, 44) time: 487274 sent: 487269 pen: 1
490469 rem: 195
[ 787.276560] lower bound violation: 0
[ 787.276615] rto: 200 (0 >> 3 + 0, 43) time: 487276 sent: 487269 pen: 1
487469 rem: 193
[ 787.276725] lower bound violation: 0
[ 787.276781] rto: 200 (0 >> 3 + 0, 42) time: 487276 sent: 487269 pen: 1
487469 rem: 193
[ 790.488206] lower bound violation: 0
[ 790.488262] rto: 200 (0 >> 3 + 0, 45) time: 490488 sent: 490269 pen: 1
493469 rem: 0
[ 790.488375] lower bound violation: 0
[ 790.488425] rto: 200 (0 >> 3 + 0, 45) time: 490488 sent: 490488 pen: 1
490888 rem: 200
[ 790.488523] lower bound violation: 0
[ 790.488570] rto: 200 (0 >> 3 + 0, 44) time: 490488 sent: 490488 pen: 1
490688 rem: 200
[ 793.498782] lower bound violation: 0
[ 793.498842] rto: 200 (0 >> 3 + 0, 47) time: 493498 sent: 493488 pen: 1
496688 rem: 190
[ 793.498953] lower bound violation: 0
[ 793.499007] rto: 200 (0 >> 3 + 0, 46) time: 493498 sent: 493488 pen: 1
493688 rem: 190
[ 793.499118] lower bound violation: 0
[ 793.499172] rto: 200 (0 >> 3 + 0, 45) time: 493499 sent: 493488 pen: 1
493689 rem: 189
[ 796.499231] lower bound violation: 0
[ 796.499296] rto: 200 (0 >> 3 + 0, 48) time: 496499 sent: 496488 pen: 1
499688 rem: 189
[ 796.499414] lower bound violation: 0
[ 796.499463] rto: 200 (0 >> 3 + 0, 47) time: 496499 sent: 496488 pen: 1
496688 rem: 189
[ 796.500131] lower bound violation: 0
[ 796.500185] rto: 200 (0 >> 3 + 0, 46) time: 496500 sent: 496488 pen: 1
496688 rem: 188
[ 799.709974] lower bound violation: 0
[ 799.710036] rto: 200 (0 >> 3 + 0, 49) time: 499710 sent: 499488 pen: 1
502688 rem: 0
[ 799.711369] lower bound violation: 0
[ 799.711428] rto: 200 (0 >> 3 + 0, 49) time: 499711 sent: 499710 pen: 1
500110 rem: 199
[ 799.711547] lower bound violation: 0
[ 799.711602] rto: 200 (0 >> 3 + 0, 48) time: 499711 sent: 499710 pen: 1
499910 rem: 199
[ 802.718498] lower bound violation: 0
[ 802.718560] rto: 200 (0 >> 3 + 0, 51) time: 502718 sent: 502710 pen: 1
505910 rem: 192
[ 802.718689] lower bound violation: 0
[ 802.718753] rto: 200 (0 >> 3 + 0, 50) time: 502718 sent: 502710 pen: 1
502910 rem: 192
[ 802.718869] lower bound violation: 0
[ 802.718921] rto: 200 (0 >> 3 + 0, 49) time: 502718 sent: 502710 pen: 1
502910 rem: 192
[ 805.714361] lower bound violation: 0
[ 805.714422] rto: 200 (0 >> 3 + 0, 52) time: 505714 sent: 505710 pen: 1
508910 rem: 196
[ 805.714533] lower bound violation: 0
[ 805.714590] rto: 200 (0 >> 3 + 0, 51) time: 505714 sent: 505710 pen: 1
505910 rem: 196
[ 805.714688] lower bound violation: 0
[ 805.714736] rto: 200 (0 >> 3 + 0, 50) time: 505714 sent: 505710 pen: 1
505910 rem: 196
[ 808.715859] lower bound violation: 0
[ 808.715919] rto: 200 (0 >> 3 + 0, 53) time: 508715 sent: 508710 pen: 1
511910 rem: 195
[ 808.716030] lower bound violation: 0
[ 808.716086] rto: 200 (0 >> 3 + 0, 52) time: 508715 sent: 508710 pen: 1
508910 rem: 195
[ 808.716185] lower bound violation: 0
[ 808.716233] rto: 200 (0 >> 3 + 0, 51) time: 508715 sent: 508710 pen: 1
508910 rem: 195
[ 811.723842] lower bound violation: 0
[ 811.723903] rto: 200 (0 >> 3 + 0, 54) time: 511723 sent: 511710 pen: 1
514910 rem: 187
[ 811.724015] lower bound violation: 0
[ 811.724073] rto: 200 (0 >> 3 + 0, 53) time: 511724 sent: 511710 pen: 1
511910 rem: 186
[ 811.724185] lower bound violation: 0
[ 811.724234] rto: 200 (0 >> 3 + 0, 52) time: 511724 sent: 511710 pen: 1
511910 rem: 186
[ 814.717152] lower bound violation: 0
[ 814.717212] rto: 200 (0 >> 3 + 0, 55) time: 514717 sent: 514710 pen: 1
517910 rem: 193
[ 814.717325] lower bound violation: 0
[ 814.717373] rto: 200 (0 >> 3 + 0, 54) time: 514717 sent: 514710 pen: 1
514910 rem: 193
[ 814.718354] lower bound violation: 0
[ 814.718407] rto: 200 (0 >> 3 + 0, 53) time: 514718 sent: 514710 pen: 1
514910 rem: 192
[ 817.907863] lower bound violation: 0
[ 817.907923] rto: 200 (0 >> 3 + 0, 56) time: 517907 sent: 517710 pen: 1
520910 rem: 3
[ 817.912287] lower bound violation: 0
[ 817.912346] rto: 200 (0 >> 3 + 0, 56) time: 517912 sent: 517911 pen: 1
518311 rem: 199
[ 817.912456] lower bound violation: 0
[ 817.912511] rto: 200 (0 >> 3 + 0, 55) time: 517912 sent: 517911 pen: 1
518111 rem: 199
[ 820.941479] lower bound violation: 0
[ 820.941539] rto: 200 (0 >> 3 + 0, 58) time: 520941 sent: 520911 pen: 1
524111 rem: 170
[ 820.941671] lower bound violation: 0
[ 820.941733] rto: 200 (0 >> 3 + 0, 57) time: 520941 sent: 520911 pen: 1
521111 rem: 170
[ 820.941846] lower bound violation: 0
[ 820.941895] rto: 200 (0 >> 3 + 0, 56) time: 520941 sent: 520911 pen: 1
521111 rem: 170
[ 824.121180] lower bound violation: 0
[ 824.121242] rto: 200 (0 >> 3 + 0, 59) time: 524121 sent: 523911 pen: 1
527111 rem: 0
[ 824.121346] lower bound violation: 0
[ 824.122108] rto: 200 (0 >> 3 + 0, 59) time: 524121 sent: 524121 pen: 1
524521 rem: 200
[ 824.123817] lower bound violation: 0
[ 824.123887] rto: 200 (0 >> 3 + 0, 58) time: 524123 sent: 524121 pen: 1
524322 rem: 198
[ 827.122286] lower bound violation: 0
[ 827.122347] rto: 200 (0 >> 3 + 0, 61) time: 527122 sent: 527121 pen: 1
530321 rem: 199
[ 827.124167] lower bound violation: 0
[ 827.124223] rto: 200 (0 >> 3 + 0, 60) time: 527124 sent: 527121 pen: 1
527321 rem: 197
[ 827.124332] lower bound violation: 0
[ 827.124389] rto: 200 (0 >> 3 + 0, 59) time: 527124 sent: 527121 pen: 1
527321 rem: 197
[ 830.124556] lower bound violation: 0
[ 830.124617] rto: 200 (0 >> 3 + 0, 62) time: 530124 sent: 530121 pen: 1
533321 rem: 197
[ 830.124729] lower bound violation: 0
[ 830.124777] rto: 200 (0 >> 3 + 0, 61) time: 530124 sent: 530121 pen: 1
530321 rem: 197
[ 830.124874] lower bound violation: 0
[ 830.124922] rto: 200 (0 >> 3 + 0, 60) time: 530124 sent: 530121 pen: 1
530321 rem: 197
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2010-01-16 14:12 ` Denys Fedoryshchenko
@ 2010-01-19 9:10 ` Damian Lukowski
2010-01-19 11:09 ` Denys Fedoryshchenko
0 siblings, 1 reply; 15+ messages in thread
From: Damian Lukowski @ 2010-01-19 9:10 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Ilpo Järvinen, netdev
Hi,
thank you for testing. So srtt and rttvar is zero in any of those cases.
Ilpo, it is a bug in tcp_rtt_estimator then, I suppose?
There is also a code comment in tcp_input.c, saying:
> * NOTE: clamping at TCP_RTO_MIN is not required, current algo
> * guarantees that rto is higher.
So we either fix tcp_rtt_estimator or simply clamp at TCP_RTO_MIN?
Damian
> On Monday 11 January 2010 15:02:34 you wrote:
>> On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
>>> Few more dumps. I notice:
>>> 1)Ack always equal 1
>>> 2)It is usually first segment of data sent (?)
>>>
>>> Maybe some value not initialised properly?
>>>
>>>
>> Can you see if the RTO lower bound is violated (I added some printing of
>> vars there too already now if it turns out to be something):
>>
>> diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
>> index 65b8ebf..d84469f 100644
>> --- a/net/ipv4/tcp_ipv4.c
>> +++ b/net/ipv4/tcp_ipv4.c
>> @@ -327,6 +327,22 @@ static void do_pmtu_discovery(struct sock *sk, struct
> Hi, i'm very sorry for delay. Just having problem with Lebanese ISP's (u pay
> 20k for 20mbit, u get 20% packetloss at peak time, and they say it is normal).
>
> I did test, here is some things from dmesg
> [ 396.496765] lower bound violation: 0
> [ 396.496833] rto: 200 (0 >> 3 + 0, 4) time: 96496 sent: 96496 pen: 1 96696
> rem: 200
> [ 399.442640] lower bound violation: 0
> [ 399.442721] rto: 200 (0 >> 3 + 0, 16) time: 99442 sent: 99421 pen: 1 102621
> rem: 179
> [ 399.444802] lower bound violation: 0
> [ 399.444881] rto: 200 (0 >> 3 + 0, 10) time: 99444 sent: 99233 pen: 1 102433
> rem: 0
> [ 399.446444] lower bound violation: 0
> [ 399.446521] rto: 200 (0 >> 3 + 0, 15) time: 99446 sent: 99421 pen: 1 99621
> rem: 175
> [ 399.539751] lower bound violation: 0
> [ 399.539832] rto: 200 (0 >> 3 + 0, 7) time: 99539 sent: 99496 pen: 1 102696
> rem: 157
> [ 399.539964] rto: 200 (0 >> 3 + 0, 6) time: 99539 sent: 99496 pen: 1 99696
> rem: 157
> [ 399.540650] rto: 200 (0 >> 3 + 0, 5) time: 99540 sent: 99496 pen: 1 99696
> rem: 156
> [ 402.445674] __ratelimit: 2 callbacks suppressed
> [ 402.445756] lower bound violation: 0
> [ 402.445833] rto: 200 (0 >> 3 + 0, 18) time: 102445 sent: 102421 pen: 1
> 105621 rem: 176
> [ 402.445958] lower bound violation: 0
> [ 402.446026] rto: 200 (0 >> 3 + 0, 13) time: 102445 sent: 102244 pen: 1
> 105444 rem: 0
> [ 402.446150] lower bound violation: 0
> [ 402.446217] rto: 200 (0 >> 3 + 0, 17) time: 102446 sent: 102421 pen: 1
> 102621 rem: 175
> [ 402.742463] lower bound violation: 0
> [ 402.742544] rto: 200 (0 >> 3 + 0, 8) time: 102742 sent: 102496 pen: 1
> 105696 rem: 0
> [ 402.743567] lower bound violation: 0
> [ 402.744361] rto: 200 (0 >> 3 + 0, 8) time: 102744 sent: 102742 pen: 1
> 103142 rem: 198
> [ 402.744478] lower bound violation: 0
> [ 402.744545] rto: 200 (0 >> 3 + 0, 7) time: 102744 sent: 102742 pen: 1
> 102942 rem: 198
> [ 405.446861] lower bound violation: 0
> [ 405.446943] rto: 200 (0 >> 3 + 0, 20) time: 105446 sent: 105421 pen: 1
> 108621 rem: 175
> [ 405.447075] lower bound violation: 0
> [ 405.447142] rto: 200 (0 >> 3 + 0, 16) time: 105446 sent: 105246 pen: 1
> 108446 rem: 0
> [ 405.447265] lower bound violation: 0
> [ 405.447332] rto: 200 (0 >> 3 + 0, 19) time: 105446 sent: 105421 pen: 1
> 105621 rem: 175
> [ 405.759226] lower bound violation: 0
> [ 405.759307] rto: 200 (0 >> 3 + 0, 10) time: 105759 sent: 105742 pen: 1
> 108942 rem: 183
> [ 405.763529] rto: 200 (0 >> 3 + 0, 9) time: 105763 sent: 105742 pen: 1
> 105942 rem: 179
> [ 405.764344] rto: 200 (0 >> 3 + 0, 8) time: 105764 sent: 105742 pen: 1
> 105942 rem: 178
> [ 408.450964] __ratelimit: 2 callbacks suppressed
> [ 408.451045] lower bound violation: 0
> [ 408.451121] rto: 200 (0 >> 3 + 0, 22) time: 108450 sent: 108421 pen: 1
> 111621 rem: 171
> [ 408.451246] lower bound violation: 0
> [ 408.451314] rto: 200 (0 >> 3 + 0, 19) time: 108450 sent: 108246 pen: 1
> 111446 rem: 0
> [ 408.451437] lower bound violation: 0
> [ 408.451504] rto: 200 (0 >> 3 + 0, 21) time: 108450 sent: 108421 pen: 1
> 108621 rem: 171
> [ 408.792229] lower bound violation: 0
> [ 408.792307] rto: 200 (0 >> 3 + 0, 11) time: 108792 sent: 108742 pen: 1
> 111942 rem: 150
> [ 408.792821] lower bound violation: 0
> [ 408.792897] rto: 200 (0 >> 3 + 0, 10) time: 108792 sent: 108742 pen: 1
> 108942 rem: 150
> [ 408.793033] lower bound violation: 0
> [ 408.793109] rto: 200 (0 >> 3 + 0, 9) time: 108793 sent: 108742 pen: 1
> 108943 rem: 149
> [ 411.478006] lower bound violation: 0
> [ 411.478088] rto: 200 (0 >> 3 + 0, 24) time: 111478 sent: 111421 pen: 1
> 114621 rem: 143
> [ 411.478220] lower bound violation: 0
> [ 411.478287] rto: 200 (0 >> 3 + 0, 22) time: 111478 sent: 111250 pen: 1
> 114450 rem: 0
> [ 411.478411] lower bound violation: 0
> [ 411.478478] rto: 200 (0 >> 3 + 0, 23) time: 111478 sent: 111421 pen: 1
> 111621 rem: 143
> [ 411.804382] lower bound violation: 0
> [ 411.804464] rto: 200 (0 >> 3 + 0, 12) time: 111804 sent: 111742 pen: 1
> 114942 rem: 138
> [ 411.804598] rto: 200 (0 >> 3 + 0, 11) time: 111804 sent: 111742 pen: 1
> 111942 rem: 138
> [ 414.498996] __ratelimit: 1 callbacks suppressed
> [ 414.499080] lower bound violation: 0
> [ 414.499160] rto: 200 (0 >> 3 + 0, 26) time: 114498 sent: 114421 pen: 1
> 117621 rem: 123
> [ 414.513129] lower bound violation: 0
> [ 414.513207] rto: 200 (0 >> 3 + 0, 25) time: 114513 sent: 114278 pen: 1
> 117478 rem: 0
> [ 414.513344] lower bound violation: 0
> [ 414.513412] rto: 200 (0 >> 3 + 0, 25) time: 114513 sent: 114421 pen: 1
> 114621 rem: 108
> [ 414.784717] lower bound violation: 0
> [ 414.784799] rto: 200 (0 >> 3 + 0, 14) time: 114784 sent: 114742 pen: 1
> 117942 rem: 158
> [ 414.786072] lower bound violation: 0
> [ 414.786152] rto: 200 (0 >> 3 + 0, 13) time: 114786 sent: 114742 pen: 1
> 114942 rem: 156
> [ 417.515995] lower bound violation: 0
> [ 417.516077] rto: 200 (0 >> 3 + 0, 28) time: 117516 sent: 117421 pen: 1
> 120621 rem: 105
> [ 417.516213] lower bound violation: 0
> [ 417.516289] rto: 200 (0 >> 3 + 0, 28) time: 117516 sent: 117313 pen: 1
> 120513 rem: 0
> [ 417.516413] lower bound violation: 0
> [ 417.516481] rto: 200 (0 >> 3 + 0, 27) time: 117516 sent: 117421 pen: 1
> 117621 rem: 105
> [ 417.803533] lower bound violation: 0
> [ 417.803615] rto: 200 (0 >> 3 + 0, 16) time: 117803 sent: 117742 pen: 1
> 120942 rem: 139
> [ 417.803745] lower bound violation: 0
> [ 417.803812] rto: 200 (0 >> 3 + 0, 15) time: 117803 sent: 117742 pen: 1
> 117942 rem: 139
> [ 417.803930] rto: 200 (0 >> 3 + 0, 14) time: 117803 sent: 117742 pen: 1
> 117942 rem: 139
> [ 420.556115] __ratelimit: 1 callbacks suppressed
> [ 420.556198] lower bound violation: 0
> [ 420.556274] rto: 200 (0 >> 3 + 0, 30) time: 120556 sent: 120421 pen: 1
> 123621 rem: 65
> [ 420.556399] lower bound violation: 0
> [ 420.556466] rto: 200 (0 >> 3 + 0, 31) time: 120556 sent: 120316 pen: 1
> 123516 rem: 0
> [ 420.556591] lower bound violation: 0
> [ 420.556659] rto: 200 (0 >> 3 + 0, 29) time: 120556 sent: 120421 pen: 1
> 120621 rem: 65
> [ 420.965666] lower bound violation: 0
> [ 420.965749] rto: 200 (0 >> 3 + 0, 17) time: 120965 sent: 120742 pen: 1
> 123942 rem: 0
> [ 420.967717] lower bound violation: 0
> [ 420.967796] rto: 200 (0 >> 3 + 0, 17) time: 120967 sent: 120965 pen: 1
> 121365 rem: 198
> [ 420.972139] lower bound violation: 0
> [ 420.972216] rto: 200 (0 >> 3 + 0, 16) time: 120972 sent: 120965 pen: 1
> 121165 rem: 193
> [ 423.564843] lower bound violation: 0
> [ 423.564924] rto: 200 (0 >> 3 + 0, 32) time: 123564 sent: 123421 pen: 1
> 126621 rem: 57
> [ 423.565062] lower bound violation: 0
> [ 423.565130] rto: 200 (0 >> 3 + 0, 34) time: 123565 sent: 123356 pen: 1
> 126556 rem: 0
> [ 423.565254] lower bound violation: 0
> [ 423.565322] rto: 200 (0 >> 3 + 0, 31) time: 123565 sent: 123421 pen: 1
> 123622 rem: 56
> [ 424.001854] lower bound violation: 0
> [ 424.001936] rto: 200 (0 >> 3 + 0, 19) time: 124001 sent: 123965 pen: 1
> 127165 rem: 164
> [ 424.005665] rto: 200 (0 >> 3 + 0, 18) time: 124005 sent: 123965 pen: 1
> 124166 rem: 160
> [ 424.007636] rto: 200 (0 >> 3 + 0, 17) time: 124007 sent: 123965 pen: 1
> 124165 rem: 158
> [ 426.580172] __ratelimit: 2 callbacks suppressed
> [ 426.580254] lower bound violation: 0
> [ 426.580337] rto: 200 (0 >> 3 + 0, 34) time: 126580 sent: 126421 pen: 1
> 129621 rem: 41
> [ 426.580456] lower bound violation: 0
> [ 426.580524] rto: 200 (0 >> 3 + 0, 37) time: 126580 sent: 126365 pen: 1
> 129565 rem: 0
> [ 426.580647] lower bound violation: 0
> [ 426.580715] rto: 200 (0 >> 3 + 0, 33) time: 126580 sent: 126421 pen: 1
> 126621 rem: 41
> [ 427.210363] lower bound violation: 0
> [ 427.210443] rto: 200 (0 >> 3 + 0, 20) time: 127210 sent: 126965 pen: 1
> 130165 rem: 0
> [ 427.210587] lower bound violation: 0
> [ 427.210654] rto: 200 (0 >> 3 + 0, 20) time: 127210 sent: 127210 pen: 1
> 127610 rem: 200
> [ 427.210770] lower bound violation: 0
> [ 427.210837] rto: 200 (0 >> 3 + 0, 19) time: 127210 sent: 127210 pen: 1
> 127410 rem: 200
> [ 429.586539] lower bound violation: 0
> [ 429.586628] rto: 200 (0 >> 3 + 0, 36) time: 129586 sent: 129421 pen: 1
> 132621 rem: 35
> [ 429.588735] lower bound violation: 0
> [ 429.588814] rto: 200 (0 >> 3 + 0, 40) time: 129588 sent: 129380 pen: 1
> 132580 rem: 0
> [ 429.589880] lower bound violation: 0
> [ 429.589957] rto: 200 (0 >> 3 + 0, 35) time: 129589 sent: 129421 pen: 1
> 129621 rem: 32
> [ 430.231164] lower bound violation: 0
> [ 430.231246] rto: 200 (0 >> 3 + 0, 22) time: 130231 sent: 130210 pen: 1
> 133410 rem: 179
> [ 430.253497] rto: 200 (0 >> 3 + 0, 21) time: 130253 sent: 130210 pen: 1
> 130410 rem: 157
> [ 432.600005] __ratelimit: 1 callbacks suppressed
> [ 432.600087] lower bound violation: 0
> [ 432.600164] rto: 200 (0 >> 3 + 0, 38) time: 132600 sent: 132421 pen: 1
> 135621 rem: 21
> [ 432.601516] lower bound violation: 0
> [ 432.601593] rto: 200 (0 >> 3 + 0, 43) time: 132601 sent: 132388 pen: 1
> 135588 rem: 0
> [ 432.601729] lower bound violation: 0
> [ 432.601796] rto: 200 (0 >> 3 + 0, 37) time: 132601 sent: 132421 pen: 1
> 132621 rem: 20
> [ 433.292095] lower bound violation: 0
> [ 433.292177] rto: 200 (0 >> 3 + 0, 24) time: 133292 sent: 133210 pen: 1
> 136410 rem: 118
> [ 433.292308] lower bound violation: 0
> [ 433.292375] rto: 200 (0 >> 3 + 0, 23) time: 133292 sent: 133210 pen: 1
> 133410 rem: 118
> [ 433.292491] lower bound violation: 0
> [ 433.292558] rto: 200 (0 >> 3 + 0, 22) time: 133292 sent: 133210 pen: 1
> 133410 rem: 118
> [ 435.624429] lower bound violation: 0
> [ 435.624512] rto: 200 (0 >> 3 + 0, 40) time: 135624 sent: 135421 pen: 1
> 138621 rem: 0
> [ 435.624649] lower bound violation: 0
> [ 435.624717] rto: 200 (0 >> 3 + 0, 46) time: 135624 sent: 135401 pen: 1
> 138601 rem: 0
> [ 435.625410] lower bound violation: 0
> [ 435.625410] rto: 200 (0 >> 3 + 0, 40) time: 135624 sent: 135624 pen: 1
> 136024 rem: 200
> [ 436.455058] lower bound violation: 0
> [ 436.455140] rto: 200 (0 >> 3 + 0, 25) time: 136455 sent: 136210 pen: 1
> 139410 rem: 0
> [ 436.455279] rto: 200 (0 >> 3 + 0, 25) time: 136455 sent: 136455 pen: 1
> 136855 rem: 200
> [ 436.455397] rto: 200 (0 >> 3 + 0, 24) time: 136455 sent: 136455 pen: 1
> 136655 rem: 200
> [ 439.507877] __ratelimit: 2 callbacks suppressed
> [ 439.507959] lower bound violation: 0
> [ 439.508037] rto: 200 (0 >> 3 + 0, 27) time: 139507 sent: 139455 pen: 1
> 142655 rem: 148
> [ 439.508161] lower bound violation: 0
> [ 439.508228] rto: 200 (0 >> 3 + 0, 26) time: 139507 sent: 139455 pen: 1
> 139655 rem: 148
> [ 442.507756] lower bound violation: 0
> [ 442.507838] rto: 200 (0 >> 3 + 0, 29) time: 142507 sent: 142455 pen: 1
> 145655 rem: 148
> [ 442.507969] lower bound violation: 0
> [ 442.508035] rto: 200 (0 >> 3 + 0, 28) time: 142507 sent: 142455 pen: 1
> 142655 rem: 148
> [ 442.508152] lower bound violation: 0
> [ 442.508219] rto: 200 (0 >> 3 + 0, 27) time: 142507 sent: 142455 pen: 1
> 142655 rem: 148
> [ 445.498049] lower bound violation: 0
> [ 445.498130] rto: 200 (0 >> 3 + 0, 30) time: 145498 sent: 145455 pen: 1
> 148655 rem: 157
> [ 445.499105] lower bound violation: 0
> [ 445.499194] rto: 200 (0 >> 3 + 0, 29) time: 145499 sent: 145455 pen: 1
> 145655 rem: 156
> [ 445.501524] lower bound violation: 0
> [ 445.501600] rto: 200 (0 >> 3 + 0, 28) time: 145501 sent: 145455 pen: 1
> 145655 rem: 154
> [ 448.678590] lower bound violation: 0
> [ 448.678671] rto: 200 (0 >> 3 + 0, 31) time: 148678 sent: 148455 pen: 1
> 151655 rem: 0
> [ 448.678808] lower bound violation: 0
> [ 448.678876] rto: 200 (0 >> 3 + 0, 31) time: 148678 sent: 148678 pen: 1
> 149078 rem: 200
> [ 451.716905] lower bound violation: 0
> [ 451.716987] rto: 200 (0 >> 3 + 0, 34) time: 151716 sent: 151678 pen: 1
> 154878 rem: 162
> [ 451.763041] lower bound violation: 0
> [ 451.763121] rto: 200 (0 >> 3 + 0, 33) time: 151763 sent: 151678 pen: 1
> 151878 rem: 115
> [ 451.763252] lower bound violation: 0
> [ 451.763320] rto: 200 (0 >> 3 + 0, 32) time: 151763 sent: 151678 pen: 1
> 151878 rem: 115
> [ 454.732396] lower bound violation: 0
> [ 454.732478] rto: 200 (0 >> 3 + 0, 35) time: 154732 sent: 154678 pen: 1
> 157878 rem: 146
> [ 454.736990] lower bound violation: 0
> [ 454.737072] rto: 200 (0 >> 3 + 0, 34) time: 154737 sent: 154678 pen: 1
> 154878 rem: 141
> [ 454.738128] lower bound violation: 0
> [ 454.738206] rto: 200 (0 >> 3 + 0, 33) time: 154738 sent: 154678 pen: 1
> 154878 rem: 140
> [ 457.894010] lower bound violation: 0
> [ 457.894098] rto: 200 (0 >> 3 + 0, 36) time: 157894 sent: 157678 pen: 1
> 160878 rem: 0
> [ 457.913672] lower bound violation: 0
> [ 457.913751] rto: 200 (0 >> 3 + 0, 36) time: 157913 sent: 157894 pen: 1
> 158294 rem: 181
> [ 457.913883] lower bound violation: 0
> [ 457.913950] rto: 200 (0 >> 3 + 0, 35) time: 157913 sent: 157894 pen: 1
> 158094 rem: 181
> [ 460.932992] lower bound violation: 0
> [ 460.933073] rto: 200 (0 >> 3 + 0, 38) time: 160932 sent: 160894 pen: 1
> 164094 rem: 162
> [ 460.933206] lower bound violation: 0
> [ 460.933273] rto: 200 (0 >> 3 + 0, 37) time: 160932 sent: 160894 pen: 1
> 161094 rem: 162
> [ 460.933390] lower bound violation: 0
> [ 460.933457] rto: 200 (0 >> 3 + 0, 36) time: 160932 sent: 160894 pen: 1
> 161094 rem: 162
> [ 463.928470] lower bound violation: 0
> [ 463.928551] rto: 200 (0 >> 3 + 0, 39) time: 163928 sent: 163894 pen: 1
> 167094 rem: 166
> [ 466.953674] lower bound violation: 0
> [ 466.953755] rto: 200 (0 >> 3 + 0, 42) time: 166953 sent: 166894 pen: 1
> 170094 rem: 141
> [ 466.953887] lower bound violation: 0
> [ 466.953954] rto: 200 (0 >> 3 + 0, 41) time: 166953 sent: 166894 pen: 1
> 167094 rem: 141
> [ 470.112498] lower bound violation: 0
> [ 470.112580] rto: 200 (0 >> 3 + 0, 44) time: 170112 sent: 169894 pen: 1
> 173094 rem: 0
> [ 470.127286] lower bound violation: 0
> [ 470.127364] rto: 200 (0 >> 3 + 0, 44) time: 170127 sent: 170112 pen: 1
> 170512 rem: 185
> [ 473.167817] lower bound violation: 0
> [ 473.167899] rto: 200 (0 >> 3 + 0, 47) time: 173167 sent: 173112 pen: 1
> 176312 rem: 145
> [ 473.168030] lower bound violation: 0
> [ 473.168098] rto: 200 (0 >> 3 + 0, 46) time: 173168 sent: 173112 pen: 1
> 173313 rem: 144
> [ 473.169413] lower bound violation: 0
> [ 473.169491] rto: 200 (0 >> 3 + 0, 45) time: 173169 sent: 173112 pen: 1
> 173312 rem: 143
> [ 522.630573] lower bound violation: 0
> [ 522.630655] rto: 200 (0 >> 3 + 0, 0) time: 222630 sent: 222630 pen: 1
> 228630 rem: 200
> [ 627.844099] lower bound violation: 0
> [ 627.844176] rto: 200 (0 >> 3 + 0, 8) time: 327844 sent: 324830 pen: 1
> 427230 rem: 0
> [ 630.848249] lower bound violation: 0
> [ 630.848333] rto: 200 (0 >> 3 + 0, 11) time: 330848 sent: 330644 pen: 1
> 333844 rem: 0
> [ 735.859328] lower bound violation: 0
> [ 735.859388] rto: 200 (0 >> 3 + 0, 19) time: 435859 sent: 432848 pen: 1
> 535248 rem: 0
> [ 738.864261] lower bound violation: 0
> [ 738.864322] rto: 200 (0 >> 3 + 0, 22) time: 438864 sent: 438659 pen: 1
> 441859 rem: 0
> [ 738.865358] lower bound violation: 0
> [ 738.865415] rto: 200 (0 >> 3 + 0, 22) time: 438865 sent: 438864 pen: 1
> 439264 rem: 199
> [ 741.864947] lower bound violation: 0
> [ 741.865007] rto: 200 (0 >> 3 + 0, 25) time: 441864 sent: 441864 pen: 1
> 445064 rem: 200
> [ 741.867651] lower bound violation: 0
> [ 741.867709] rto: 200 (0 >> 3 + 0, 24) time: 441867 sent: 441864 pen: 1
> 442065 rem: 197
> [ 741.867821] lower bound violation: 0
> [ 741.867875] rto: 200 (0 >> 3 + 0, 23) time: 441867 sent: 441864 pen: 1
> 442064 rem: 197
> [ 744.874165] lower bound violation: 0
> [ 744.874225] rto: 200 (0 >> 3 + 0, 26) time: 444874 sent: 444864 pen: 1
> 448064 rem: 190
> [ 744.874340] lower bound violation: 0
> [ 744.874388] rto: 200 (0 >> 3 + 0, 25) time: 444874 sent: 444864 pen: 1
> 445064 rem: 190
> [ 744.874486] lower bound violation: 0
> [ 744.874535] rto: 200 (0 >> 3 + 0, 24) time: 444874 sent: 444864 pen: 1
> 445064 rem: 190
> [ 747.874311] lower bound violation: 0
> [ 747.874373] rto: 200 (0 >> 3 + 0, 27) time: 447874 sent: 447864 pen: 1
> 451064 rem: 190
> [ 747.874474] lower bound violation: 0
> [ 747.874523] rto: 200 (0 >> 3 + 0, 26) time: 447874 sent: 447864 pen: 1
> 448064 rem: 190
> [ 747.874628] lower bound violation: 0
> [ 747.874677] rto: 200 (0 >> 3 + 0, 25) time: 447874 sent: 447864 pen: 1
> 448064 rem: 190
> [ 750.870109] lower bound violation: 0
> [ 750.870170] rto: 200 (0 >> 3 + 0, 28) time: 450870 sent: 450864 pen: 1
> 454064 rem: 194
> [ 750.870281] lower bound violation: 0
> [ 750.870330] rto: 200 (0 >> 3 + 0, 27) time: 450870 sent: 450864 pen: 1
> 451064 rem: 194
> [ 750.870435] lower bound violation: 0
> [ 750.870484] rto: 200 (0 >> 3 + 0, 26) time: 450870 sent: 450864 pen: 1
> 451064 rem: 194
> [ 753.882598] lower bound violation: 0
> [ 753.882661] rto: 200 (0 >> 3 + 0, 29) time: 453882 sent: 453864 pen: 1
> 457064 rem: 182
> [ 753.882779] lower bound violation: 0
> [ 753.882842] rto: 200 (0 >> 3 + 0, 28) time: 453882 sent: 453864 pen: 1
> 454064 rem: 182
> [ 753.882975] lower bound violation: 0
> [ 753.883050] rto: 200 (0 >> 3 + 0, 27) time: 453883 sent: 453864 pen: 1
> 454064 rem: 181
> [ 756.874204] lower bound violation: 0
> [ 756.874265] rto: 200 (0 >> 3 + 0, 30) time: 456874 sent: 456864 pen: 1
> 460064 rem: 190
> [ 756.874376] lower bound violation: 0
> [ 756.874424] rto: 200 (0 >> 3 + 0, 29) time: 456874 sent: 456864 pen: 1
> 457064 rem: 190
> [ 756.874527] lower bound violation: 0
> [ 756.874576] rto: 200 (0 >> 3 + 0, 28) time: 456874 sent: 456864 pen: 1
> 457064 rem: 190
> [ 759.891416] lower bound violation: 0
> [ 759.891480] rto: 200 (0 >> 3 + 0, 31) time: 459891 sent: 459864 pen: 1
> 463064 rem: 173
> [ 759.891591] lower bound violation: 0
> [ 759.891647] rto: 200 (0 >> 3 + 0, 30) time: 459891 sent: 459864 pen: 1
> 460064 rem: 173
> [ 759.891746] lower bound violation: 0
> [ 759.892390] rto: 200 (0 >> 3 + 0, 29) time: 459891 sent: 459864 pen: 1
> 460064 rem: 173
> [ 763.066046] lower bound violation: 0
> [ 763.066106] rto: 200 (0 >> 3 + 0, 32) time: 463066 sent: 462864 pen: 1
> 466064 rem: 0
> [ 763.066224] lower bound violation: 0
> [ 763.066273] rto: 200 (0 >> 3 + 0, 32) time: 463066 sent: 463066 pen: 1
> 463466 rem: 200
> [ 763.066371] lower bound violation: 0
> [ 763.066419] rto: 200 (0 >> 3 + 0, 31) time: 463066 sent: 463066 pen: 1
> 463266 rem: 200
> [ 766.065427] lower bound violation: 0
> [ 766.065501] rto: 200 (0 >> 3 + 0, 33) time: 466065 sent: 464466 pen: 1
> 466066 rem: 0
> [ 766.069012] lower bound violation: 0
> [ 766.069070] rto: 200 (0 >> 3 + 0, 33) time: 466068 sent: 466065 pen: 1
> 466465 rem: 197
> [ 766.069184] lower bound violation: 0
> [ 766.069242] rto: 200 (0 >> 3 + 0, 32) time: 466069 sent: 466065 pen: 1
> 466266 rem: 196
> [ 769.077813] lower bound violation: 0
> [ 769.077873] rto: 200 (0 >> 3 + 0, 35) time: 469077 sent: 469065 pen: 1
> 472265 rem: 188
> [ 769.077985] lower bound violation: 0
> [ 769.078043] rto: 200 (0 >> 3 + 0, 34) time: 469078 sent: 469065 pen: 1
> 469265 rem: 187
> [ 772.078686] lower bound violation: 0
> [ 772.078746] rto: 200 (0 >> 3 + 0, 37) time: 472078 sent: 472065 pen: 1
> 475265 rem: 187
> [ 772.078859] lower bound violation: 0
> [ 772.078907] rto: 200 (0 >> 3 + 0, 36) time: 472078 sent: 472065 pen: 1
> 472265 rem: 187
> [ 772.079674] lower bound violation: 0
> [ 772.079731] rto: 200 (0 >> 3 + 0, 35) time: 472079 sent: 472065 pen: 1
> 472265 rem: 186
> [ 775.269432] lower bound violation: 0
> [ 775.269494] rto: 200 (0 >> 3 + 0, 38) time: 475269 sent: 475065 pen: 1
> 478265 rem: 0
> [ 775.270671] lower bound violation: 0
> [ 775.270733] rto: 200 (0 >> 3 + 0, 38) time: 475270 sent: 475269 pen: 1
> 475669 rem: 199
> [ 775.270848] lower bound violation: 0
> [ 775.270897] rto: 200 (0 >> 3 + 0, 37) time: 475270 sent: 475269 pen: 1
> 475469 rem: 199
> [ 778.277343] lower bound violation: 0
> [ 778.277404] rto: 200 (0 >> 3 + 0, 40) time: 478277 sent: 478269 pen: 1
> 481469 rem: 192
> [ 778.277536] lower bound violation: 0
> [ 778.277602] rto: 200 (0 >> 3 + 0, 39) time: 478277 sent: 478269 pen: 1
> 478469 rem: 192
> [ 778.277722] lower bound violation: 0
> [ 778.277778] rto: 200 (0 >> 3 + 0, 38) time: 478277 sent: 478269 pen: 1
> 478469 rem: 192
> [ 781.272677] lower bound violation: 0
> [ 781.272737] rto: 200 (0 >> 3 + 0, 41) time: 481272 sent: 481269 pen: 1
> 484469 rem: 197
> [ 781.272850] lower bound violation: 0
> [ 781.272898] rto: 200 (0 >> 3 + 0, 40) time: 481272 sent: 481269 pen: 1
> 481469 rem: 197
> [ 784.274886] lower bound violation: 0
> [ 784.274946] rto: 200 (0 >> 3 + 0, 43) time: 484274 sent: 484269 pen: 1
> 487469 rem: 195
> [ 784.275064] lower bound violation: 0
> [ 784.275112] rto: 200 (0 >> 3 + 0, 42) time: 484275 sent: 484269 pen: 1
> 484470 rem: 194
> [ 784.275212] lower bound violation: 0
> [ 784.275260] rto: 200 (0 >> 3 + 0, 41) time: 484275 sent: 484269 pen: 1
> 484469 rem: 194
> [ 787.274753] lower bound violation: 0
> [ 787.274814] rto: 200 (0 >> 3 + 0, 44) time: 487274 sent: 487269 pen: 1
> 490469 rem: 195
> [ 787.276560] lower bound violation: 0
> [ 787.276615] rto: 200 (0 >> 3 + 0, 43) time: 487276 sent: 487269 pen: 1
> 487469 rem: 193
> [ 787.276725] lower bound violation: 0
> [ 787.276781] rto: 200 (0 >> 3 + 0, 42) time: 487276 sent: 487269 pen: 1
> 487469 rem: 193
> [ 790.488206] lower bound violation: 0
> [ 790.488262] rto: 200 (0 >> 3 + 0, 45) time: 490488 sent: 490269 pen: 1
> 493469 rem: 0
> [ 790.488375] lower bound violation: 0
> [ 790.488425] rto: 200 (0 >> 3 + 0, 45) time: 490488 sent: 490488 pen: 1
> 490888 rem: 200
> [ 790.488523] lower bound violation: 0
> [ 790.488570] rto: 200 (0 >> 3 + 0, 44) time: 490488 sent: 490488 pen: 1
> 490688 rem: 200
> [ 793.498782] lower bound violation: 0
> [ 793.498842] rto: 200 (0 >> 3 + 0, 47) time: 493498 sent: 493488 pen: 1
> 496688 rem: 190
> [ 793.498953] lower bound violation: 0
> [ 793.499007] rto: 200 (0 >> 3 + 0, 46) time: 493498 sent: 493488 pen: 1
> 493688 rem: 190
> [ 793.499118] lower bound violation: 0
> [ 793.499172] rto: 200 (0 >> 3 + 0, 45) time: 493499 sent: 493488 pen: 1
> 493689 rem: 189
> [ 796.499231] lower bound violation: 0
> [ 796.499296] rto: 200 (0 >> 3 + 0, 48) time: 496499 sent: 496488 pen: 1
> 499688 rem: 189
> [ 796.499414] lower bound violation: 0
> [ 796.499463] rto: 200 (0 >> 3 + 0, 47) time: 496499 sent: 496488 pen: 1
> 496688 rem: 189
> [ 796.500131] lower bound violation: 0
> [ 796.500185] rto: 200 (0 >> 3 + 0, 46) time: 496500 sent: 496488 pen: 1
> 496688 rem: 188
> [ 799.709974] lower bound violation: 0
> [ 799.710036] rto: 200 (0 >> 3 + 0, 49) time: 499710 sent: 499488 pen: 1
> 502688 rem: 0
> [ 799.711369] lower bound violation: 0
> [ 799.711428] rto: 200 (0 >> 3 + 0, 49) time: 499711 sent: 499710 pen: 1
> 500110 rem: 199
> [ 799.711547] lower bound violation: 0
> [ 799.711602] rto: 200 (0 >> 3 + 0, 48) time: 499711 sent: 499710 pen: 1
> 499910 rem: 199
> [ 802.718498] lower bound violation: 0
> [ 802.718560] rto: 200 (0 >> 3 + 0, 51) time: 502718 sent: 502710 pen: 1
> 505910 rem: 192
> [ 802.718689] lower bound violation: 0
> [ 802.718753] rto: 200 (0 >> 3 + 0, 50) time: 502718 sent: 502710 pen: 1
> 502910 rem: 192
> [ 802.718869] lower bound violation: 0
> [ 802.718921] rto: 200 (0 >> 3 + 0, 49) time: 502718 sent: 502710 pen: 1
> 502910 rem: 192
> [ 805.714361] lower bound violation: 0
> [ 805.714422] rto: 200 (0 >> 3 + 0, 52) time: 505714 sent: 505710 pen: 1
> 508910 rem: 196
> [ 805.714533] lower bound violation: 0
> [ 805.714590] rto: 200 (0 >> 3 + 0, 51) time: 505714 sent: 505710 pen: 1
> 505910 rem: 196
> [ 805.714688] lower bound violation: 0
> [ 805.714736] rto: 200 (0 >> 3 + 0, 50) time: 505714 sent: 505710 pen: 1
> 505910 rem: 196
> [ 808.715859] lower bound violation: 0
> [ 808.715919] rto: 200 (0 >> 3 + 0, 53) time: 508715 sent: 508710 pen: 1
> 511910 rem: 195
> [ 808.716030] lower bound violation: 0
> [ 808.716086] rto: 200 (0 >> 3 + 0, 52) time: 508715 sent: 508710 pen: 1
> 508910 rem: 195
> [ 808.716185] lower bound violation: 0
> [ 808.716233] rto: 200 (0 >> 3 + 0, 51) time: 508715 sent: 508710 pen: 1
> 508910 rem: 195
> [ 811.723842] lower bound violation: 0
> [ 811.723903] rto: 200 (0 >> 3 + 0, 54) time: 511723 sent: 511710 pen: 1
> 514910 rem: 187
> [ 811.724015] lower bound violation: 0
> [ 811.724073] rto: 200 (0 >> 3 + 0, 53) time: 511724 sent: 511710 pen: 1
> 511910 rem: 186
> [ 811.724185] lower bound violation: 0
> [ 811.724234] rto: 200 (0 >> 3 + 0, 52) time: 511724 sent: 511710 pen: 1
> 511910 rem: 186
> [ 814.717152] lower bound violation: 0
> [ 814.717212] rto: 200 (0 >> 3 + 0, 55) time: 514717 sent: 514710 pen: 1
> 517910 rem: 193
> [ 814.717325] lower bound violation: 0
> [ 814.717373] rto: 200 (0 >> 3 + 0, 54) time: 514717 sent: 514710 pen: 1
> 514910 rem: 193
> [ 814.718354] lower bound violation: 0
> [ 814.718407] rto: 200 (0 >> 3 + 0, 53) time: 514718 sent: 514710 pen: 1
> 514910 rem: 192
> [ 817.907863] lower bound violation: 0
> [ 817.907923] rto: 200 (0 >> 3 + 0, 56) time: 517907 sent: 517710 pen: 1
> 520910 rem: 3
> [ 817.912287] lower bound violation: 0
> [ 817.912346] rto: 200 (0 >> 3 + 0, 56) time: 517912 sent: 517911 pen: 1
> 518311 rem: 199
> [ 817.912456] lower bound violation: 0
> [ 817.912511] rto: 200 (0 >> 3 + 0, 55) time: 517912 sent: 517911 pen: 1
> 518111 rem: 199
> [ 820.941479] lower bound violation: 0
> [ 820.941539] rto: 200 (0 >> 3 + 0, 58) time: 520941 sent: 520911 pen: 1
> 524111 rem: 170
> [ 820.941671] lower bound violation: 0
> [ 820.941733] rto: 200 (0 >> 3 + 0, 57) time: 520941 sent: 520911 pen: 1
> 521111 rem: 170
> [ 820.941846] lower bound violation: 0
> [ 820.941895] rto: 200 (0 >> 3 + 0, 56) time: 520941 sent: 520911 pen: 1
> 521111 rem: 170
> [ 824.121180] lower bound violation: 0
> [ 824.121242] rto: 200 (0 >> 3 + 0, 59) time: 524121 sent: 523911 pen: 1
> 527111 rem: 0
> [ 824.121346] lower bound violation: 0
> [ 824.122108] rto: 200 (0 >> 3 + 0, 59) time: 524121 sent: 524121 pen: 1
> 524521 rem: 200
> [ 824.123817] lower bound violation: 0
> [ 824.123887] rto: 200 (0 >> 3 + 0, 58) time: 524123 sent: 524121 pen: 1
> 524322 rem: 198
> [ 827.122286] lower bound violation: 0
> [ 827.122347] rto: 200 (0 >> 3 + 0, 61) time: 527122 sent: 527121 pen: 1
> 530321 rem: 199
> [ 827.124167] lower bound violation: 0
> [ 827.124223] rto: 200 (0 >> 3 + 0, 60) time: 527124 sent: 527121 pen: 1
> 527321 rem: 197
> [ 827.124332] lower bound violation: 0
> [ 827.124389] rto: 200 (0 >> 3 + 0, 59) time: 527124 sent: 527121 pen: 1
> 527321 rem: 197
> [ 830.124556] lower bound violation: 0
> [ 830.124617] rto: 200 (0 >> 3 + 0, 62) time: 530124 sent: 530121 pen: 1
> 533321 rem: 197
> [ 830.124729] lower bound violation: 0
> [ 830.124777] rto: 200 (0 >> 3 + 0, 61) time: 530124 sent: 530121 pen: 1
> 530321 rem: 197
> [ 830.124874] lower bound violation: 0
> [ 830.124922] rto: 200 (0 >> 3 + 0, 60) time: 530124 sent: 530121 pen: 1
> 530321 rem: 197
> --
> To unsubscribe from this list: send the line "unsubscribe netdev" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2010-01-19 9:10 ` Damian Lukowski
@ 2010-01-19 11:09 ` Denys Fedoryshchenko
2010-01-19 11:17 ` Ilpo Järvinen
0 siblings, 1 reply; 15+ messages in thread
From: Denys Fedoryshchenko @ 2010-01-19 11:09 UTC (permalink / raw)
To: Damian Lukowski, Ilpo Järvinen, netdev
On Tuesday 19 January 2010 11:10:12 you wrote:
> Hi,
> thank you for testing. So srtt and rttvar is zero in any of those cases.
> Ilpo, it is a bug in tcp_rtt_estimator then, I suppose?
>
> There is also a code comment in tcp_input.c, saying:
> > * NOTE: clamping at TCP_RTO_MIN is not required, current algo
> > * guarantees that rto is higher.
>
> So we either fix tcp_rtt_estimator or simply clamp at TCP_RTO_MIN?
>
> Damian
>
> > On Monday 11 January 2010 15:02:34 you wrote:
> >> On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
> >>> Few more dumps. I notice:
> >>> 1)Ack always equal 1
> >>> 2)It is usually first segment of data sent (?)
> >>>
> >>> Maybe some value not initialised properly?
> >>
> >> Can you see if the RTO lower bound is violated (I added some printing of
> >> vars there too already now if it turns out to be something):
> >>
> >> diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
> >> index 65b8ebf..d84469f 100644
> >> --- a/net/ipv4/tcp_ipv4.c
> >> +++ b/net/ipv4/tcp_ipv4.c
As i see in code it is rounding RTO to minimum value.
It fixes my problem seems.
Btw just a bit about my environment - wireless networks (sometimes lossy!)
with low speed (128-512Kbps) customers working over pppoe. Maybe it will give
a tip why rtt value is too low.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2010-01-19 11:09 ` Denys Fedoryshchenko
@ 2010-01-19 11:17 ` Ilpo Järvinen
2010-01-23 21:37 ` Denys Fedoryshchenko
0 siblings, 1 reply; 15+ messages in thread
From: Ilpo Järvinen @ 2010-01-19 11:17 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Damian Lukowski, Netdev
On Tue, 19 Jan 2010, Denys Fedoryshchenko wrote:
> On Tuesday 19 January 2010 11:10:12 you wrote:
> > Hi,
> > thank you for testing. So srtt and rttvar is zero in any of those cases.
> > Ilpo, it is a bug in tcp_rtt_estimator then, I suppose?
> >
> > There is also a code comment in tcp_input.c, saying:
> > > * NOTE: clamping at TCP_RTO_MIN is not required, current algo
> > > * guarantees that rto is higher.
> >
> > So we either fix tcp_rtt_estimator or simply clamp at TCP_RTO_MIN?
> >
> > Damian
> >
> > > On Monday 11 January 2010 15:02:34 you wrote:
> > >> On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
> > >>> Few more dumps. I notice:
> > >>> 1)Ack always equal 1
> > >>> 2)It is usually first segment of data sent (?)
> > >>>
> > >>> Maybe some value not initialised properly?
> > >>
> > >> Can you see if the RTO lower bound is violated (I added some printing of
> > >> vars there too already now if it turns out to be something):
> > >>
> > >> diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
> > >> index 65b8ebf..d84469f 100644
> > >> --- a/net/ipv4/tcp_ipv4.c
> > >> +++ b/net/ipv4/tcp_ipv4.c
> As i see in code it is rounding RTO to minimum value.
> It fixes my problem seems.
>
> Btw just a bit about my environment - wireless networks (sometimes lossy!)
> with low speed (128-512Kbps) customers working over pppoe. Maybe it will give
> a tip why rtt value is too low.
What I find most strange in it is the fact that when it triggers for the
first time, the srtt and mdev are zero, not some value in between 0 and
200ms. Therefore I suspect that this case might be something that we've
overlooked where srtt/mdev are not valid at all.
Maybe the patch below helps...
--
i.
--
diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
index 65b8ebf..c8166d7 100644
--- a/net/ipv4/tcp_ipv4.c
+++ b/net/ipv4/tcp_ipv4.c
@@ -401,6 +417,9 @@ void tcp_v4_err(struct sk_buff *icmp_skb, u32 info)
* (see draft-zimmermann-tcp-lcd) */
if (code != ICMP_NET_UNREACH && code != ICMP_HOST_UNREACH)
break;
+ /* A bit too strict, just want to be on the safe side for now */
+ if (sk->sk_state != TCP_ESTABLISHED)
+ break;
if (seq != tp->snd_una || !icsk->icsk_retransmits ||
!icsk->icsk_backoff)
break;
^ permalink raw reply related [flat|nested] 15+ messages in thread
* Re: Crazy TCP bug (keepalive flood?) in 2.6.32?
2010-01-19 11:17 ` Ilpo Järvinen
@ 2010-01-23 21:37 ` Denys Fedoryshchenko
0 siblings, 0 replies; 15+ messages in thread
From: Denys Fedoryshchenko @ 2010-01-23 21:37 UTC (permalink / raw)
To: Ilpo Järvinen, netdev
On Tuesday 19 January 2010 13:17:51 you wrote:
> On Tue, 19 Jan 2010, Denys Fedoryshchenko wrote:
> > On Tuesday 19 January 2010 11:10:12 you wrote:
> > > Hi,
> > > thank you for testing. So srtt and rttvar is zero in any of those
> > > cases. Ilpo, it is a bug in tcp_rtt_estimator then, I suppose?
> > >
> > > There is also a code comment in tcp_input.c, saying:
> > > > * NOTE: clamping at TCP_RTO_MIN is not required, current algo
> > > > * guarantees that rto is higher.
> > >
> > > So we either fix tcp_rtt_estimator or simply clamp at TCP_RTO_MIN?
> > >
> > > Damian
> > >
> > > > On Monday 11 January 2010 15:02:34 you wrote:
> > > >> On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
> > > >>> Few more dumps. I notice:
> > > >>> 1)Ack always equal 1
> > > >>> 2)It is usually first segment of data sent (?)
> > > >>>
> > > >>> Maybe some value not initialised properly?
> > > >>
> > > >> Can you see if the RTO lower bound is violated (I added some
> > > >> printing of vars there too already now if it turns out to be
> > > >> something):
> > > >>
> > > >> diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
> > > >> index 65b8ebf..d84469f 100644
> > > >> --- a/net/ipv4/tcp_ipv4.c
> > > >> +++ b/net/ipv4/tcp_ipv4.c
> >
> > As i see in code it is rounding RTO to minimum value.
> > It fixes my problem seems.
> >
> > Btw just a bit about my environment - wireless networks (sometimes
> > lossy!) with low speed (128-512Kbps) customers working over pppoe. Maybe
> > it will give a tip why rtt value is too low.
>
> What I find most strange in it is the fact that when it triggers for the
> first time, the srtt and mdev are zero, not some value in between 0 and
> 200ms. Therefore I suspect that this case might be something that we've
> overlooked where srtt/mdev are not valid at all.
>
> Maybe the patch below helps...
>
Seems after this patch (and debug patch with warnings) my dmesg is clean.
^ permalink raw reply [flat|nested] 15+ messages in thread
end of thread, other threads:[~2010-01-23 21:35 UTC | newest]
Thread overview: 15+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2009-12-09 18:51 Crazy TCP bug (keepalive flood?) in 2.6.32? Denys Fedoryshchenko
2009-12-10 8:24 ` Ilpo Järvinen
2009-12-10 8:28 ` Ilpo Järvinen
2009-12-10 8:50 ` Ilpo Järvinen
2009-12-10 10:05 ` Damian Lukowski
2009-12-10 10:24 ` Ilpo Järvinen
2009-12-26 14:54 ` Denys Fedoryshchenko
2009-12-26 15:03 Denys Fedoryshchenko
2009-12-26 19:24 ` Ilpo Järvinen
2010-01-11 13:02 ` Ilpo Järvinen
2010-01-16 14:12 ` Denys Fedoryshchenko
2010-01-19 9:10 ` Damian Lukowski
2010-01-19 11:09 ` Denys Fedoryshchenko
2010-01-19 11:17 ` Ilpo Järvinen
2010-01-23 21:37 ` Denys Fedoryshchenko
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.