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

[Paul Cager]

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).
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20130130/39e399db/attachment.htm>