From owner-freebsd-net@FreeBSD.ORG Mon Nov 5 09:18:38 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 8A1C0B4C for ; Mon, 5 Nov 2012 09:18:38 +0000 (UTC) (envelope-from andre@freebsd.org) Received: from c00l3r.networx.ch (c00l3r.networx.ch [62.48.2.2]) by mx1.freebsd.org (Postfix) with ESMTP id 0876F8FC19 for ; Mon, 5 Nov 2012 09:18:36 +0000 (UTC) Received: (qmail 80227 invoked from network); 5 Nov 2012 10:54:17 -0000 Received: from c00l3r.networx.ch (HELO [127.0.0.1]) ([62.48.2.2]) (envelope-sender ) by c00l3r.networx.ch (qmail-ldap-1.03) with SMTP for ; 5 Nov 2012 10:54:17 -0000 Message-ID: <50978469.8000001@freebsd.org> Date: Mon, 05 Nov 2012 10:18:33 +0100 From: Andre Oppermann User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:16.0) Gecko/20121010 Thunderbird/16.0.1 MIME-Version: 1.0 To: Fabian Keil Subject: Re: kern/173309: [tcp] TCP connections often prematurely closed by the server side after r242262 [regression] References: <201211032251.qA3Mpnp6017076@freefall.freebsd.org> <5095B953.9060301@freebsd.org> <20121104132957.3965dc99@fabiankeil.de> <5096C6CA.4090306@freebsd.org> <20121104225226.500507a3@fabiankeil.de> <5096E8FD.6040103@freebsd.org> <20121105002509.670ca1fc@fabiankeil.de> In-Reply-To: <20121105002509.670ca1fc@fabiankeil.de> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Cc: freebsd-net@freebsd.org 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: Mon, 05 Nov 2012 09:18:38 -0000 On 05.11.2012 00:25, Fabian Keil wrote: > Andre Oppermann wrote: > >> On 04.11.2012 22:52, Fabian Keil wrote: >>> Andre Oppermann wrote: > >>>> 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, >> >> That's good. >> >>> 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=1; while curl -o /dev/zero 'http://127.0.0.1:81/90k-file'; do echo $i; ((i=$i+1)); done >>> % Total % Received % Xferd Average Speed Time Time Time Current >>> Dload Upload Total Spent Left Speed >>> 100 90000 100 90000 0 0 364k 0 --:--:-- --:--:-- --:--:-- 366k >>> 1 >>> % Total % Received % Xferd Average Speed Time Time Time Current >>> Dload Upload Total Spent Left Speed >>> 100 90000 100 90000 0 0 799k 0 --:--:-- --:--:-- --:--:-- 806k >>> 2 >>> % Total % Received % Xferd Average Speed Time Time Time Current >>> Dload Upload Total Spent Left Speed >>> 99 90000 99 89742 0 0 363k 0 --:--:-- --:--:-- --:--:-- 365k >>> curl: (18) transfer closed with 258 bytes remaining to read >> >> This message from curl points to a problem in the interaction between the >> server and curl. See this description: >> http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=572276 >> >> So unless you can rule out a curl/privoxy interop issue and with gatling it >> is working reliably we can assume this particular TCP problem to be fixed. >> >> Here on my test machine with nginx it works realiably as well again. There >> is an interesting edge case with socket buffer autoscaling on loopback but >> that is neither fatal nor related to this problem. > > Sorry, my description was a bit misleading. I didn't mean that Privoxy is > generating HTTP chunks (in which case the Debian bug might apply), > but that it uses one write() call per ~4999 bytes of data. > > I work on Privoxy upstream, the regression tests rely on curl and > there weren't any (known) compatibility issues before r242262. > > In the above setup, Privoxy is acting as proxy between curl and gatling > and just passes on the received data in a read/write loop. > > If I let curl request a document Privoxy serves itself and thus can > send it with a single write() call, the problem happens a lot less > often. > > Probably your nginx setup is closer to this scenario. Maybe you can > reproduce the problem by running two nginx instances and letting > the first one act as a proxy before the second one. > >>> In this cases Privoxy wrote most of the response body in chunks of >>> 4999 bytes, near the end of the transfer write() returned -1: >> >> The write returns -1 because the client (curl) has closed the socket and >> the last write can be accepted anymore. Curl has prematurely closed the >> connection. > > The tcpdump from my previous message seems to show that the server > side is closing the connection: > > 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:90013}], 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, win 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 1275, 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 Thank you for the detailed report and testing. I've backed out the change with r242601 as it exhibits still too many problems. I'll fix these problems in the next days but in the mean time HEAD should be in a working state. I'll be grateful if I could send you the fixed change for testing before it goes into HEAD again. -- Andre