search

ninenines / gun

HTTP/1.1, HTTP/2, Websocket client (and more) for Erlang/OTP.
ISC License
891 stars 232 forks source link

Websocket "closed" every time after open without a reason #255

Closed vboikotriller closed 3 years ago

vboikotriller commented 3 years ago

For reason unknown Gun terminates connection to Cowboy websocket server.

Client code: """ -behaviour(gen_server).

start_link(DBPath) -> gen_server:start_link({local, ?MODULE}, ?MODULE, [DBPath], []).

ws_connect() -> gen_server:cast(?MODULE, ws_connect).

start_ws() -> .. case gun:open(Host, Port, #{transport => tcp, protocols => [http]}) of {ok, ConnPid} -> case gun:await_up(ConnPid) of {ok, http} -> StreamRef = gun:ws_upgrade(ConnPid, "/somewhere", [ .. headers ..]), wait_for_ws_upgrade(ConnPid, StreamRef, 5000) end end.

wait_for_ws_upgrade(ConnPid, StreamRef, Timeout) -> receive {gunupgrade, ConnPid, StreamRef, [<<"websocket">>], } -> ResponseHeader = binary:encode_unsigned(?PT_INFO_REQUEST), Packet = << 0, ResponseHeader/binary, <<0:(19 * 8)>>/binary, 1, 0, 0 >>, gun:ws_send(ConnPid, StreamRef, {text, Packet}); {gunresponse, ConnPid, , _, Status, _Headers} -> {error, io_lib:format("Status: ~s", [Status])}; {gun_error, ConnPid, _StreamRef, Reason} -> {error, io_lib:format("gun_error: ~p", [Reason])} after Timeout -> {error, timeout} end. """

Server code: """ init(Req0, _Opts) -> {cowboy_websocket, Req0, [{device_id, DeviceId}..]. websocket_init(State) -> {ok, State}. websocket_handle({text, Data}, State) -> {ok, State}; .. """

Client's debug log: """ (<0.699.0>) call gun:connected(info,{tcp_closed,#Port<0.498>},{state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,#Port<0.498>,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   gun_http,
   {http_state,#Port<0.498>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,
               undefined,[],head,
               {0,0},
               head},
   undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun:handle_common_connected(info,{tcp_closed,#Port<0.498>},connected,{state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,#Port<0.498>,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   gun_http,
   {http_state,#Port<0.498>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,
               undefined,[],head,
               {0,0},
               head},
   undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun:handle_common_connected_no_input(info,{tcp_closed,#Port<0.498>},connected,{state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,#Port<0.498>,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   gun_http,
   {http_state,#Port<0.498>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,
               undefined,[],head,
               {0,0},
               head},
   undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun:disconnect({state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,#Port<0.498>,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   gun_http,
   {http_state,#Port<0.498>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,
               undefined,[],head,
               {0,0},
               head},
   undefined,gun_default_event_h,undefined},closed)

(<0.699.0>) call gun_http:close(closed,{http_state,#Port<0.498>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,undefined,[], head, {0,0}, head},gun_default_event_h,undefined) (<0.699.0>) call gun_http:close_reason(closed) (<0.699.0>) call gun_http:close_streams({http_state,#Port<0.498>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,undefined,[], head, {0,0}, head},[],closed) (<0.699.0>) call gun:disconnect_flush({state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,#Port<0.498>,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   gun_http,
   {http_state,#Port<0.498>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,
               undefined,[],head,
               {0,0},
               head},
   undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun_http:down({http_state,#Port<0.498>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,undefined,[], head, {0,0}, head}) (<0.699.0>) call gun_http:'-down/1-lc$^0/1-0-'([]) (<0.699.0>) call gun_http:name() (<0.699.0>) call gun:keepalive_cancel({state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,undefined,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   undefined,undefined,undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun:not_connected(internal,{retries,5,closed},{state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,undefined,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   undefined,undefined,undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun:'-not_connected/3-fun-0-'(5,#{protocols => [http],transport => tcp}) (<0.699.0>) call gun:default_retry_fun(5,#{protocols => [http],transport => tcp}) (<0.699.0>) call gun:domain_lookup(state_timeout,{retries,4,not_connected},{state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,undefined,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   undefined,undefined,undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun:connecting(internal,{retries,4,

{ip_addresses => [{127,0,0,1}],

       port => 8048,tcp_module => inet_tcp,
       tcp_opts => [binary,{active,false},{packet,raw}]}},{state,<0.680.0>,
   {up,#Ref<0.3466771083.542375937.13924>},
   "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],
   #{protocols => [http],transport => tcp},
   undefined,undefined,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   undefined,undefined,undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun:connected(internal,{connected,#Port<0.523>,http},{state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,undefined,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   undefined,undefined,undefined,gun_default_event_h,undefined})

gun_up (<0.699.0>) call gun_http:opts_name() (<0.699.0>) call gun_http:init(<0.680.0>,#Port<0.523>,gun_tcp,#{}) (<0.699.0>) call gun_http:name() (<0.699.0>) call gun:active({state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,#Port<0.523>,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   gun_http,
   {http_state,#Port<0.523>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,
               undefined,[],head,
               {0,0},
               head},
   undefined,gun_default_event_h,undefined})

(<0.699.0>) call gun_http:has_keepalive() (<0.699.0>) call gun:keepalive_timeout({state,<0.680.0>, {up,#Ref<0.3466771083.542375937.13924>}, "127.0.0.1",8048,<<"http">>,"127.0.0.1",8048,[],

{protocols => [http],transport => tcp},

   undefined,#Port<0.523>,gun_tcp,true,
   {tcp,tcp_closed,tcp_error},
   gun_http,
   {http_state,#Port<0.523>,gun_tcp,#{},'HTTP/1.1',keepalive,<<>>,
               undefined,[],head,
               {0,0},
               head},
   undefined,gun_default_event_h,undefined})

"""

"""

essen commented 3 years ago

Your log starts with Gun receiving a tcp_closed message which means the server has closed the connection. Why, good question, the server or an intermediary if any would tell you. Could just be a timeout.

vboikotriller commented 3 years ago

The request on server looks the following way. """

{bindings => #{},body_length => 0,cert => undefined,

               has_body => false,
               headers =>
                   #{<<"connection">> => <<"upgrade">>,
                     <<"host">> => <<"127.0.0.1:8048">>,
                     <<"sec-websocket-key">> =>
                         <<"khVLKTS5zxSLxWrpgagdTg==">>,
                     <<"sec-websocket-version">> => <<"13">>,
                     <<"upgrade">> => <<"websocket">>,
                     <<"x-transducer-device-id">> => <<"free">>,
                     <<"x-transducer-namespace">> => <<"eva.herford">>,
                     <<"x-transducer-token">> =>
                         <<"8dc67ec2-16cf-46f5-8b18-d440f43232a2">>},
               host => <<"127.0.0.1">>,host_info => undefined,
               method => <<"GET">>,path => <<"/something/">>,
               path_info => undefined,
               peer => {{127,0,0,1},54623},
               pid => <0.4215.0>,port => 8048,qs => <<>>,ref => main,
               scheme => <<"http">>,
               sock => {{127,0,0,1},8048},
               streamid => 1,version => 'HTTP/1.1'}

"""

It seems the disconnection happens when I send binary data: {reply, {text, Data}, State};

Where data is <<128,2,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1,0,0>>

How to get more information from Cowboy to track down that issue ?

Thank you.

essen commented 3 years ago

If you're sending binary data you need to use a binary frame, text frames must be valid UTF-8. So replace text with binary.

vboikotriller commented 3 years ago

It would be nice if "gun" has sent error code in that case. I spent a day trying to find the reason of disconnects. It was not obvious and not documented behavior.

essen commented 3 years ago

You're supposed to get a gun_ws message for a close frame and then a gun_down message, but it's possible the former got lost in transit if Cowboy closes the connection too quickly.