From owner-freebsd-net@FreeBSD.ORG Sun Nov 4 21:55:31 2012 Return-Path: Delivered-To: freebsd-net@FreeBSD.org Received: from mx1.freebsd.org (mx1.freebsd.org [69.147.83.52]) by hub.freebsd.org (Postfix) with ESMTP id E73C3705; Sun, 4 Nov 2012 21:55:31 +0000 (UTC) (envelope-from freebsd-listen@fabiankeil.de) Received: from smtprelay04.ispgateway.de (smtprelay04.ispgateway.de [80.67.29.8]) by mx1.freebsd.org (Postfix) with ESMTP id 56C208FC0C; Sun, 4 Nov 2012 21:55:30 +0000 (UTC) Received: from [78.35.133.171] (helo=fabiankeil.de) by smtprelay04.ispgateway.de with esmtpsa (SSLv3:AES128-SHA:128) (Exim 4.68) (envelope-from ) id 1TV89c-0008EY-Qx; Sun, 04 Nov 2012 22:54:52 +0100 Date: Sun, 4 Nov 2012 22:52:26 +0100 From: Fabian Keil To: Andre Oppermann 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> Mime-Version: 1.0 Content-Type: multipart/signed; micalg=PGP-SHA1; boundary="Sig_/ImanUpxKjV_MSJJzuDjb3mG"; protocol="application/pgp-signature" X-Df-Sender: Nzc1MDY3 Cc: freebsd-net@FreeBSD.org, null@pozo.com X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 04 Nov 2012 21:55:32 -0000 --Sig_/ImanUpxKjV_MSJJzuDjb3mG Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: quoted-printable Andre Oppermann wrote: > On 04.11.2012 13:29, Fabian Keil wrote: > > Andre Oppermann 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; 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; 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; 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; 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; 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--