[erlang-bugs] httpc: function_clause crash in http_transport:close/2

[Magnus Mueller]

Hello List,

we detected an error in httpc. It happened in R16B01 on Mac OS X, but should be around in new versions as well if my argument below is valid. I could not reproduce the issue yet and think there is a race condition. The error occurred while requesting a page over http. I attached the error report at the end of the mail.


====== Preliminary Analysis

`http_transport:close/2` crashes due to a function_clause error. As the socket argument of the function equals `{remote_close,Socket}`,  and because this is run over http, we can be sure that the following `handle_info/2` clause was run before `terminate/2` was called:
 
handle_info({tcp_closed, _}, #state{session = Session0} = State) ->
    Socket  = Session0#session.socket,
    Session = Session0#session{socket = {remote_close, Socket}},
    %% {stop, session_remotly_closed, State};
    {stop, normal, State#state{session = Session}};

This leaves the question why the argument `SocketType` in the call to `http_transport:close/2` is `undefined`. The only reason I could think of was that the initial send  request in  `httpc_handler:connect_and_send_first_request/3` failed. If that happens, `SocketType` is not added to `#session{}`. Also, the field `#session.id` is  `undefined`. The value of `#session.id` leads to the execution of the following `httpc_handler:terminate/2` clause:

terminate(normal, 
          #state{session = #session{id = undefined} = Session}) ->  
    close_socket(Session);

The call `close_socket/1` here then leads to the error reported below.


====== Order of events which might trigger the issue

Summarizing, I think that the following order of events triggers the error report below:

1. A call to `httpc_handler:connect_and_send_first_request/3`
2. The socket is opened successfully, but closes immediately after that, which leads to a `{tcp_closed,Socket}` message being send to the handler process
3. The handler tries to send the initial request over the socket and fails, leaving `#session.socket_type` and `#session.id` undefined
4. The handler sends `{init_error,error_sending,_}` to itself. This message is BEHIND the `{tcp_closed,_}` message in the queue.
5. The handler enters its loop and processes `{tcp_closed,Socket}`
6.  The `handle_info/2` call results in `{stop,normal,_}`. `#session.socket` is set to `{ remote_close,Socket}`
7. `terminate/2` is called and the clause which matches `#session.id=undefined` is chosen
8. This clause runs `httpc_handler:close_socket/1`, which then calls `http_transport:close_socket/2`. This last call fails then.

====== Possible Fix

If the analysis is correct, fixing this problem should be possible by ensuring that `#session.socket_type` is not set to undefined when `#session.socket` is set. There are also two `terminate/2` clauses to handle initialization errors, but as far as I see they are not called here:

%% Init error there is no socket to be closed.
terminate(normal, 
          #state{request = Request, 
                 session = {send_failed, AReason} = Reason} = State) ->
    ?hcrd("terminate", [{send_reason, AReason}, {request, Request}]),
    maybe_send_answer(Request, 
                      httpc_response:error(Request, Reason), 
                      State),
    ok; 

terminate(normal, 
          #state{request = Request, 
                 session = {connect_failed, AReason} = Reason} = State) ->
    ?hcrd("terminate", [{connect_reason, AReason}, {request, Request}]),
    maybe_send_answer(Request, 
                      httpc_response:error(Request, Reason), 
                      State),
    ok;

====== Ending notes

As noted in the beginning of the mail, I was not able to reproduce the error below. I tried to add `timer:sleep/1` calls to `httpc_handler` in order to force the order of events above, but that did not help either. Thus, I could be mistaken with my analysis above. I hope someone else can shed some light on this issu

Regards, Magnus

P.s. Here goes the lengthy error report:

=ERROR REPORT==== 10-Mar-2014::16:34:36 ===
** Generic server <0.12244.2> terminating 
** Last message in was {tcp_closed,#Port<0.112265>}
** When Server state == {state,
                            {request,#Ref<0.0.9.188247>,<0.11566.2>,0,http,
                                {"127.0.0.1",63178},
                                "<retracted>",
                                "?<retracted>",get,
                                {http_request_h,undefined,"close",undefined,
                                    undefined,undefined,undefined,undefined,
                                    undefined,undefined,undefined,undefined,
                                    undefined,undefined,undefined,undefined,
                                    undefined,undefined,undefined,undefined,
                                    undefined,undefined,undefined,undefined,
                                    undefined,undefined,undefined,undefined,
                                    undefined,undefined,undefined,undefined,
                                    "0",undefined,undefined,undefined,
                                    undefined,undefined,undefined,[]},
                                {[],[]},
                                {http_options,"HTTP/1.0",4700,true,
                                    {essl,[]},
                                    undefined,false,4700,false},
                                "http://ip:port/<retracted>",
                                [],none,[],1394465676042,undefined,
                                [{active,once}],
                                false},
                            {session,undefined,undefined,undefined,
                                {remote_close,#Port<0.112265>},
                                undefined,1,undefined,false},
                            undefined,undefined,undefined,undefined,
                            {[],[]},
                            {[],[]},
                            undefined,[],nolimit,nolimit,
                            {options,
                                {undefined,[]},
                                {undefined,[]},
                                0,0,0,120000,0,disabled,false,inet,default,
                                default,[]},
                            {timers,[],undefined},
                            httpc_manager,inactive}
** Reason for termination == 
** {function_clause,[{http_transport,close,
                                     [undefined,
                                      {remote_close,#Port<0.112265>}],
                                     [{file,"http_transport.erl"},{line,422}]},
                     {gen_server,terminate,6,
                                 [{file,"gen_server.erl"},{line,719}]},
                     {proc_lib,init_p_do_apply,3,
                               [{file,"proc_lib.erl"},{line,239}]}]}