[erlang-questions] Following a send_timeout inet:close() no longer closes the socket.

[Steve Vinoski]

Hi Paul,

To add to what Lukas explained, using your test program on both OS X and
Linux, lsof initially shows both the client socket and the server socket
open while sending is occurring:

beam.smp 23986 steve    9u  IPv4 969680      0t0      TCP
localhost:48399->localhost:1616 (ESTABLISHED)
beam.smp 23986 steve   10u  IPv4 969681      0t0      TCP
localhost:1616->localhost:48399 (ESTABLISHED)

If you enable {send_timeout_close,true}, once the sender hits its timeout,
the server socket gets closed just as it should, and only the client socket
remains open:

beam.smp 23986 steve    9u  IPv4 969680      0t0      TCP
localhost:48399->localhost:1616 (ESTABLISHED)

Your client isn't closed because it's passive and there's unreceived data
in the socket. If you extend your client to recv the data that was sent, it
gets {error, closed} immediately once all the data the server sent is
consumed, and at that point lsof shows the client socket is also closed. As
Lukas hinted, once you hand data to TCP it's going to try to keep sending,
as that's what it's designed to do.

Perhaps you can instead explain what you're trying to achieve, and maybe we
can steer you in the right direction?

--steve


On Mon, Feb 11, 2013 at 9:58 AM, Lukas Larsson
<lukas@REDACTED>wrote:

> Hello,
>
> If you do not use {send_timeout_close, true} on the socket, the stack will
> try to send the data until it succeeds or the remote end closes the
> connection. This means that the close will wait for the send buffer to
> clear before closing the connection.
>
> The same is true when using port_close. The inet driver logic will detect
> that there is data on the way out and wait for that data to be sent
> before closing.
>
> So to get the behaviour you want you should set send_timeout_close to
> true, setting this to true is also the recommended in the setting in the
> documentation.
>
> I also noticed that in your testcase you did not close the listen socket
> after the test was done which caused the testcase to leave the listen
> socket open in between runs.
>
> Lukas
>
>
> On Thu, Jan 31, 2013 at 12:45 AM, Paul Cager <paul.cager@REDACTED> wrote:
>
>> I am seeing a problem with erts-5.9.3.1 regarding TCP and send_timeout.
>> Please see the example program, below, but to summarise it:
>>
>>   *  A server accepts an incoming connection with options {send_timeout,
>> 250}.
>>   *  The server continually writes data until it gets an {error,
>> timeout}. The server then calls inet:close(Sock).
>>   *  However the socket isn't actually closed - netstat reports that it
>> is still established (and stays that way for at least an hour, probably for
>> ever).
>>   *  I've enabled debug tracing in drivers/common/inet_drv.c (+ added a
>> couple of debugs to show the return value of inet_subscribe). I've also
>> added tracing to show when desc_close is being called in that module.
>>   *  Normally calling inet:close() results in tcp_inet_stop and
>> desc_close being called. When inet:close() is called *after* an {error,
>> timeout} response "inet_ctl(606): INET_REQ_SUBSCRIBE" is called, but not
>> tcp_inet_stop (or desc_close), which is consistent with the socket
>> remaining ESTABLISHED.
>>   *  Using port_close rather than inet:close shows the same behaviour.
>>
>> That does not sound like the correct behaviour.
>>
>> Here is the debug output for a "normal" inet:close():
>>
>> tcp_inet_ctl(606): 24
>> inet_ctl(606): INET_REQ_SUBSCRIBE
>> inet_ctl(606): Calling inet_subscribe
>>  inet_subscribe returned 6
>> tcp_inet_stop(606) {s=10
>> deq(606): queue empty
>>  release_buffer: 1460
>> tcp_inet_stop(606) }
>> desc_close(606): 10
>>
>> Here is the debug output when receiving a {error, timeout} and calling
>> inet:close():
>>
>> tcp_sendv(606): s=10, about to send 0,8192 bytes
>>  tcp_sendv(606): s=10, only sent 512/2 of 8192/2 bytes/items
>> tcp_sendv(606): s=10, Send failed, queuing
>>  sock_select(606): flags=02, onoff=1, event_mask=03
>> tcp_inet_commandv(606) }
>>  tcp_inet_commanv(606) {s=10
>> tcp_sendv(606): s=10, sender forced busy
>> tcp_inet_commandv(606) }
>>  tcp_inet_timeout(606) {s=10
>> inet_reply_error_am 35 523
>> tcp_inet_timeout(606) }
>>  ** timeout - closing
>> ** CLOSING port_info: {connected,<0.2.0>}
>> tcp_inet_ctl(606): 24
>>  inet_ctl(606): INET_REQ_SUBSCRIBE
>> inet_ctl(606): Calling inet_subscribe
>> inet_subscribe returned 6
>>  tcp_inet_ctl(606): 11
>> inet_ctl(606): GETSTAT
>>
>> Do you have any ideas why this happens?
>>
>>
>> TEST PROGRAM
>> =============
>>
>> -module(test_tcp_close).
>>
>> -compile(export_all).
>>
>> main() ->
>> {ok, LSock} = gen_tcp:listen(1616, [binary, {packet,0}, {active, false},
>> {reuseaddr, true}]),
>>
>> spawn(?MODULE, connect_and_idle, [1616]),
>>
>> {ok, Sock} = gen_tcp:accept(LSock),
>>
>> io:format("** Accepted a connection~n", []),
>>
>> ok = inet:setopts(Sock, [
>>  %% {send_timeout, 250}, {send_timeout_close, true},
>> {send_timeout, 250},
>>  {active, once}, {nodelay, true}, {sndbuf, 131072}, {keepalive, true}
>> ]),
>>
>>  fill_write(Sock).
>>
>> fill_write(Sock) ->
>> %% Make sure the output buffer becomes full so we trigger send_timeout.
>>  Size = 8 * 1024 * 8, %% 8 KB (k *bytes*).
>>  case gen_tcp:send(Sock, <<0:Size>>) of
>> {error, timeout} ->
>>  io:format("** timeout - closing~n", []),
>> io:format("** CLOSING port_info: ~p~n", [catch erlang:port_info(Sock,
>> connected)]),
>>  inet:close(Sock),
>> %% Wait at least INET_CLOSE_TIMEOUT and a bit
>> timer:sleep(10000),
>>  io:format("** CLOSED port_info: ~p~n", [catch erlang:port_info(Sock,
>> connected)]);
>> {error, X} ->
>>  io:format("** Unexpected send error: ~p~n", [X]),
>> io:format("** port_info: ~p~n", [catch erlang:port_info(Sock,
>> connected)]);
>>  ok ->
>> %% Uncomment to test an early close
>> %% io:format("** Closing Sock early~n", []),
>>  %% inet:close(Sock),
>> %% io:format("** Closed~n", []),
>> timer:sleep(1000),
>>  fill_write(Sock)
>> end.
>>
>> connect_and_idle(Port) ->
>>  {ok, _Sock} = gen_tcp:connect("localhost", Port, [{active,false},
>> {mode,binary}, {packet, 0}]),
>> timer:sleep(infinity).
>>
>> _______________________________________________
>> erlang-questions mailing list
>> erlang-questions@REDACTED
>> http://erlang.org/mailman/listinfo/erlang-questions
>>
>>
>
> _______________________________________________
> erlang-questions mailing list
> erlang-questions@REDACTED
> http://erlang.org/mailman/listinfo/erlang-questions
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20130211/b467626d/attachment.htm>