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

[Lukas Larsson]

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
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20130211/17d0516a/attachment.htm>