Date: Sun, 4 Nov 2012 22:52:26 +0100 From: Fabian Keil <freebsd-listen@fabiankeil.de> To: Andre Oppermann <andre@freebsd.org> Cc: freebsd-net@FreeBSD.org, null@pozo.com Subject: Re: kern/173309: [tcp] TCP connections often prematurely closed by the server side after r242262 [regression] Message-ID: <20121104225226.500507a3@fabiankeil.de> In-Reply-To: <5096C6CA.4090306@freebsd.org> References: <201211032251.qA3Mpnp6017076@freefall.freebsd.org> <5095B953.9060301@freebsd.org> <20121104132957.3965dc99@fabiankeil.de> <5096C6CA.4090306@freebsd.org>
next in thread | previous in thread | raw e-mail | index | archive | help
--Sig_/ImanUpxKjV_MSJJzuDjb3mG Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: quoted-printable Andre Oppermann <andre@freebsd.org> wrote: > On 04.11.2012 13:29, Fabian Keil wrote: > > Andre Oppermann <andre@freebsd.org> wrote: > > > >> thank you for the bug report. Please try the attached patch > >> which should fix the issue you observed. > > > > Thanks for the patch, Andre. > > > > It seems to make the transfers 100% reliably again, > > but they are frequently very slow: =20 > The patch I sent was not correct. Please try this new attached patch > instead. This seems to fix the issue for connections between curl and gatling, I'm still frequently seeing problems with curl and Privoxy, though: fk@r500 ~ $echo $http_proxy http://10.0.0.1:8118/ fk@r500 ~ $i=3D1; while curl -o /dev/zero 'http://127.0.0.1:81/90k-file'; d= o echo $i; ((i=3D$i+1)); done % Total % Received % Xferd Average Speed Time Time Time Cur= rent Dload Upload Total Spent Left Spe= ed 100 90000 100 90000 0 0 364k 0 --:--:-- --:--:-- --:--:-- 3= 66k 1 % Total % Received % Xferd Average Speed Time Time Time Cur= rent Dload Upload Total Spent Left Spe= ed 100 90000 100 90000 0 0 799k 0 --:--:-- --:--:-- --:--:-- 8= 06k 2 % Total % Received % Xferd Average Speed Time Time Time Cur= rent Dload Upload Total Spent Left Spe= ed 99 90000 99 89742 0 0 363k 0 --:--:-- --:--:-- --:--:-- 3= 65k curl: (18) transfer closed with 258 bytes remaining to read In this cases Privoxy wrote most of the response body in chunks of 4999 bytes, near the end of the transfer write() returned -1: 22:34:01.342943 IP (tos 0x0, ttl 64, id 31042, offset 0, flags [DF], proto = TCP (6), length 60) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [S], seq 815402461, win 65535, op= tions [mss 16344,nop,wscale 6,sackOK,TS val 1684019208 ecr 0], length 0 22:34:01.343041 IP (tos 0x0, ttl 64, id 31043, offset 0, flags [DF], proto = TCP (6), length 60) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [S.], seq 4122285051, ack 8154024= 62, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 3752298629 ecr= 1684019208], length 0 22:34:01.343093 IP (tos 0x0, ttl 64, id 31044, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [.], seq 1, ack 1, win 1275, opti= ons [nop,nop,TS val 1684019208 ecr 3752298629], length 0 22:34:01.343970 IP (tos 0x0, ttl 64, id 31045, offset 0, flags [DF], proto = TCP (6), length 254) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [P.], seq 1:203, ack 1, win 1275,= options [nop,nop,TS val 1684019209 ecr 3752298629], length 202 22:34:01.353719 IP (tos 0x0, ttl 64, id 31057, offset 0, flags [DF], proto = TCP (6), length 322) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [P.], seq 1:271, ack 203, win 127= 5, options [nop,nop,TS val 3752298640 ecr 1684019209], length 270 22:34:01.353883 IP (tos 0x0, ttl 64, id 31058, offset 0, flags [DF], proto = TCP (6), length 16384) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [.], seq 271:16603, ack 203, win = 1275, options [nop,nop,TS val 3752298640 ecr 1684019209], length 16332 22:34:01.353925 IP (tos 0x0, ttl 64, id 31059, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [.], seq 203, ack 16603, win 1020= , options [nop,nop,TS val 1684019219 ecr 3752298640], length 0 22:34:01.353983 IP (tos 0x0, ttl 64, id 31060, offset 0, flags [DF], proto = TCP (6), length 3476) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [P.], seq 16603:20027, ack 203, w= in 1275, options [nop,nop,TS val 3752298640 ecr 1684019219], length 3424 22:34:01.354103 IP (tos 0x0, ttl 64, id 31062, offset 0, flags [DF], proto = TCP (6), length 16384) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [.], seq 20027:36359, ack 203, wi= n 1275, options [nop,nop,TS val 3752298640 ecr 1684019219], length 16332 22:34:01.354168 IP (tos 0x0, ttl 64, id 31064, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [.], seq 203, ack 36359, win 712,= options [nop,nop,TS val 1684019220 ecr 3752298640], length 0 22:34:01.354207 IP (tos 0x0, ttl 64, id 31065, offset 0, flags [DF], proto = TCP (6), length 8715) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [P.], seq 36359:45022, ack 203, w= in 1275, options [nop,nop,TS val 3752298641 ecr 1684019220], length 8663 22:34:01.354299 IP (tos 0x0, ttl 64, id 31066, offset 0, flags [DF], proto = TCP (6), length 16384) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [.], seq 45022:61354, ack 203, wi= n 1275, options [nop,nop,TS val 3752298641 ecr 1684019220], length 16332 22:34:01.354346 IP (tos 0x0, ttl 64, id 31067, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [.], seq 203, ack 61354, win 321,= options [nop,nop,TS val 1684019220 ecr 3752298641], length 0 22:34:01.354378 IP (tos 0x0, ttl 64, id 31069, offset 0, flags [DF], proto = TCP (6), length 8715) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [P.], seq 61354:70017, ack 203, w= in 1275, options [nop,nop,TS val 3752298641 ecr 1684019220], length 8663 22:34:01.354710 IP (tos 0x0, ttl 64, id 31071, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [.], seq 203, ack 70017, win 698,= options [nop,nop,TS val 1684019220 ecr 3752298641], length 0 22:34:01.354825 IP (tos 0x0, ttl 64, id 31073, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [.], seq 203, ack 70017, win 1210= , options [nop,nop,TS val 1684019220 ecr 3752298641], length 0 22:34:01.355049 IP (tos 0x0, ttl 64, id 31075, offset 0, flags [DF], proto = TCP (6), length 3716) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [FP.], seq 86349:90013, ack 203, = win 1275, options [nop,nop,TS val 3752298641 ecr 1684019220], length 3664 22:34:01.355107 IP (tos 0x0, ttl 64, id 31076, offset 0, flags [DF], proto = TCP (6), length 64) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [.], seq 203, ack 70017, win 1275= , options [nop,nop,TS val 1684019220 ecr 3752298641,nop,nop,sack 1 {86349:9= 0013}], length 0 22:34:01.588185 IP (tos 0x0, ttl 64, id 31079, offset 0, flags [DF], proto = TCP (6), length 16384) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [.], seq 70017:86349, ack 203, wi= n 1275, options [nop,nop,TS val 3752298875 ecr 1684019220], length 16332 22:34:01.588268 IP (tos 0x0, ttl 64, id 31080, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [.], seq 203, ack 90014, win 963,= options [nop,nop,TS val 1684019454 ecr 3752298875], length 0 22:34:01.588946 IP (tos 0x0, ttl 64, id 31081, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.55930 > 10.0.0.1.8118: Flags [F.], seq 203, ack 90014, win 127= 5, options [nop,nop,TS val 1684019454 ecr 3752298875], length 0 22:34:01.588999 IP (tos 0x0, ttl 64, id 31082, offset 0, flags [DF], proto = TCP (6), length 52) 10.0.0.1.8118 > 10.0.0.1.55930: Flags [.], seq 90014, ack 204, win 1275= , options [nop,nop,TS val 3752298875 ecr 1684019454], length 0 Most of the time the failures aren't logged by the kernel, but occasionally they result in messages like these: Nov 4 22:44:15 r500 kernel: [1431] TCP: [10.0.0.1]:81 to [10.0.0.1]:10946 = tcpflags 0x18<PUSH,ACK>; tcp_do_segment: FIN_WAIT_2: Received 284 bytes of = data after socket was closed, sending RST and removing tcpcb Nov 4 22:44:29 r500 kernel: [1445] TCP: [10.0.0.1]:81 to [10.0.0.1]:45803 = tcpflags 0x18<PUSH,ACK>; tcp_do_segment: FIN_WAIT_2: Received 284 bytes of = data after socket was closed, sending RST and removing tcpcb Nov 4 22:45:52 r500 kernel: [1527] TCP: [10.0.0.1]:81 to [10.0.0.1]:30760 = tcpflags 0x18<PUSH,ACK>; tcp_do_segment: FIN_WAIT_2: Received 284 bytes of = data after socket was closed, sending RST and removing tcpcb Nov 4 22:45:55 r500 kernel: [1531] TCP: [10.0.0.1]:81 to [10.0.0.1]:62527 = tcpflags 0x18<PUSH,ACK>; tcp_do_segment: FIN_WAIT_2: Received 284 bytes of = data after socket was closed, sending RST and removing tcpcb Nov 4 22:45:58 r500 kernel: [1534] TCP: [10.0.0.1]:81 to [10.0.0.1]:45876 = tcpflags 0x18<PUSH,ACK>; tcp_do_segment: FIN_WAIT_2: Received 284 bytes of = data after socket was closed, sending RST and removing tcpcb Fabian --Sig_/ImanUpxKjV_MSJJzuDjb3mG Content-Type: application/pgp-signature; name=signature.asc Content-Disposition: attachment; filename=signature.asc -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.19 (FreeBSD) iEYEARECAAYFAlCW450ACgkQBYqIVf93VJ0kqwCgjnlcy+Hf0KPOIO/zSeRzStHh r3UAoJDFKd7mGqfw1QqaBq90Dc+IzBnY =0Opv -----END PGP SIGNATURE----- --Sig_/ImanUpxKjV_MSJJzuDjb3mG--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20121104225226.500507a3>