Skip site navigation (1)Skip section navigation (2)
Date:      Sun, 04 Nov 2012 23:15:25 +0100
From:      Andre Oppermann <andre@freebsd.org>
To:        Fabian Keil <freebsd-listen@fabiankeil.de>
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:  <5096E8FD.6040103@freebsd.org>
In-Reply-To: <20121104225226.500507a3@fabiankeil.de>
References:  <201211032251.qA3Mpnp6017076@freefall.freebsd.org> <5095B953.9060301@freebsd.org> <20121104132957.3965dc99@fabiankeil.de> <5096C6CA.4090306@freebsd.org> <20121104225226.500507a3@fabiankeil.de>

next in thread | previous in thread | raw e-mail | index | archive | help
On 04.11.2012 22:52, Fabian Keil wrote:
> 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:
>
>> 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.

> 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.

-snip-
> 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

When the socket was abruptly closed by the client and the server still
had data in flight you're going to see this message.  This is normal and
expected.

-- 
Andre




Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?5096E8FD.6040103>