http2_client request crashing in http2_stream.half_closed_local

[lucacorti]

I'm using http2_client.start_link/3 to connect to a server and send requests. With both sync and async requests I get the following crash when sending the first request:

00:57:50.056 [error] ** State machine #PID<0.409.0> terminating
** Last event in was :recv_es
** When State == :half_closed_local
** Data == {:stream_state, 1, #PID<0.402.0>,
{:ssl,
{:sslsocket, {:gen_tcp, #Port<0.13518>, :tls_connection, :undefined},
#PID<0.406.0>}}, :idle, 65535, 65535, {[], []}, {[], []},
[{":method", "POST"}, {":scheme", "https"},
{":authority", "api.development.push.apple.com"},
{"accept", "application/json"}, {"accept-encoding", "gzip, deflate"},
{":path",
"/3/device/b9f91716e547ea82e8441a86b8a9f57bcd720cf73e02ad35062fbec3ee241ecb"},
{":apns-expiration", "0"}, {":apns-priority", "10"}], :undefined, false,
false,
[{":status", "200"}, {"apns-id", "F42F5426-89BC-750B-3E65-6EFAF71859BF"}],
:undefined, false, false, :undefined, :undefined, #PID<0.368.0>,
{:cb_static, []}, :chatterbox_static_stream}
** Reason for termination =
** {:function_clause,
[{:http2_stream, :half_closed_local,
[:recv_es,
{:stream_state, 1, #PID<0.402.0>,
{:ssl,
{:sslsocket, {:gen_tcp, #Port<0.13518>, :tls_connection, :undefined},
#PID<0.406.0>}}, :idle, 65535, 65535, {[], []}, {[], []},
[{":method", "POST"}, {":scheme", "https"},
{":authority", "api.development.push.apple.com"},
{"accept", "application/json"}, {"accept-encoding", "gzip, deflate"},
{":path",
"/3/device/b9f91716e547ea82e8441a86b8a9f57bcd720cf73e02ad35062fbec3ee241ecb"},
{":apns-expiration", "0"}, {":apns-priority", "10"}], :undefined, false,
false,
[{":status", "200"}, {"apns-id", "F42F5426-89BC-750B-3E65-6EFAF71859BF"}],
:undefined, false, false, :undefined, :undefined, #PID<0.368.0>,
{:cb_static, []}, :chatterbox_static_stream}],
[file: 'src/http2_stream.erl', line: 480]},
{:gen_fsm, :handle_msg, 7, [file: 'gen_fsm.erl', line: 518]},
{:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 240]}]}

00:57:50.056 [error] gen_fsm <0.409.0> in state half_closed_local terminated with reason: no function clause matching http2_stream:half_closed_local(r
ecv_es, {stream_state,1,<0.402.0>,{ssl,{sslsocket,{gen_tcp,#Port<0.13518>,tls_connection,undefined},<0.406.0>}},...}) line 480
00:57:50.056 [error] CRASH REPORT Process <0.409.0> with 3 neighbours exited with reason: no function clause matching http2_stream:half_closed_local(r
ecv_es, {stream_state,1,<0.402.0>,{ssl,{sslsocket,{gen_tcp,#Port<0.13518>,tls_connection,undefined},<0.406.0>}},...}) line 480 in gen_fsm:terminate/7
line 626
00:57:50.056 [error] Supervisor {<0.363.0>,poolboy_sup} had child undefined started with {'Elixir.Cartel.Pusher.Apns2',start_link,undefined} at <0.368
.0> exit with reason no function clause matching http2_stream:half_closed_local(recv_es, {stream_state,1,<0.402.0>,{ssl,{sslsocket,{gen_tcp,#Port<0.13
518>,tls_connection,undefined},<0.406.0>}},...}) line 480 in context child_terminated
** (exit) exited in: GenServer.call(#PID<0.368.0>, {:send, %Cartel.Message.Apns2{expiration: 0, id: nil, payload: %{aps: %{alert: "ciao"}}, priority:
10, token: "b9f91716e547ea82e8441a86b8a9f57bcd720cf73e02ad35062fbec3ee241ecb", topic: nil}}, 5000)
** (EXIT) an exception was raised:
** (FunctionClauseError) no function clause matching in :http2_stream.half_closed_local/2
(chatterbox) src/http2_stream.erl:480: :http2_stream.half_closed_local(:recv_es, {:stream_state, 1, #PID<0.402.0>, {:ssl, {:sslsocket, {:g
en_tcp, #Port<0.13518>, :tls_connection, :undefined}, #PID<0.406.0>}}, :idle, 65535, 65535, {[], []}, {[], []}, [{":method", "POST"}, {":scheme", "htt
ps"}, {":authority", "api.development.push.apple.com"}, {"accept", "application/json"}, {"accept-encoding", "gzip, deflate"}, {":path", "/3/device/b9f
91716e547ea82e8441a86b8a9f57bcd720cf73e02ad35062fbec3ee241ecb"}, {":apns-expiration", "0"}, {":apns-priority", "10"}], :undefined, false, false, [{":s
tatus", "200"}, {"apns-id", "F42F5426-89BC-750B-3E65-6EFAF71859BF"}], :undefined, false, false, :undefined, :undefined, #PID<0.368.0>, {:cb_static, []
}, :chatterbox_static_stream})
(stdlib) gen_fsm.erl:518: :gen_fsm.handle_msg/7
(stdlib) proc_lib.erl:240: :proc_lib.init_p_do_apply/3
(elixir) lib/gen_server.ex:564: GenServer.call/3
(poolboy) src/poolboy.erl:76: :poolboy.transaction/3

[slezakattack]

I have a patch for this. I'll try to submit either today or tomorrow when I'm free.

[slezakattack]

After looking at master branch, it looks like this might be fixed already? Have you updated upstream master lately?

[joedevivo]

I have been pushing to master, resolving issues found with https://github.com/summerwind/h2spec and it's entirely possible this has been fixed.

I meant to ask if there's a specific test case anybody has for this. I'm happy to include it.

[slezakattack]

My HTTP/2 knowledge is a bit limited but the bug was that http2_stream:half_closed_local was getting a 'recv_es' message. However, it seems that http2_stream seemed to have "jumped the gun" or something and tried to detect an 'end-of-stream' flag in the last frame and then close the stream. I guess Apple's APNs servers don't send an END_STREAM in the last frame? Basically, there was a disconnect between receiving frames and closing the stream.

I'm not sure what the test case is for this but...hopefully this info gives you an idea of what test case you would add. :/

[lucacorti]

Apparently mix was getting an older commit from master. After updating it, sync_request times out, but I know the request gets through, so it seems no END_STREAM is received as @slezakattack says.

** (exit) exited in: GenServer.call(#PID<0.218.0>, {:send, %Cartel.Message.Apns2{expiration: 0, id: nil, payload: %{aps: %{alert: "ciao"}}, priority:
10, token: "b9f91716e547ea82e8441a86b8a9f57bcd720cf73e02ad35062fbec3ee241ecb", topic: nil}}, 5000)
** (EXIT) time out
(elixir) lib/gen_server.ex:564: GenServer.call/3
(poolboy) src/poolboy.erl:76: :poolboy.transaction/3
19:51:56.084 [error] GenServer #PID<0.218.0> terminating
** (MatchError) no match of right hand side value: {:error, :timeout}
(cartel) lib/cartel/pusher/apns2.ex:77: Cartel.Pusher.Apns2.handle_call/3
(stdlib) gen_server.erl:629: :gen_server.try_handle_call/4
(stdlib) gen_server.erl:661: :gen_server.handle_msg/5
(stdlib) proc_lib.erl:240: :proc_lib.init_p_do_apply/3
Last message: {:send, %Cartel.Message.Apns2{expiration: 0, id: nil, payload: %{aps: %{alert: "ciao"}}, priority: 10, token: "b9f91716e547ea82e8441a86b
8a9f57bcd720cf73e02ad35062fbec3ee241ecb", topic: nil}}
State: %{conf: %{cacert: "/Users/luca/Desktop/keys/entrust_2048_ca.cer", cert: "/Users/luca/Desktop/keys/tsc-apns-dev-crt.pem", env: :sandbox, key: "/
Users/luca/Desktop/keys/tsc-apns-dev-key.pem", type: Cartel.Pusher.Apns2}, headers: nil, pid: nil}
19:51:56.084 [error] gen_server <0.218.0> terminated with reason: no match of right hand value {error,timeout} in 'Elixir.Cartel.Pusher.Apns2':handle_
call/3 line 77
19:51:56.084 [error] CRASH REPORT Process <0.218.0> with 2 neighbours exited with reason: no match of right hand value {error,timeout} in 'Elixir.Cart
el.Pusher.Apns2':handle_call/3 line 77 in gen_server:terminate/7 line 826
19:51:56.085 [error] Supervisor {<0.213.0>,poolboy_sup} had child undefined started with {'Elixir.Cartel.Pusher.Apns2',start_link,undefined} at <0.218
.0> exit with reason no match of right hand value {error,timeout} in 'Elixir.Cartel.Pusher.Apns2':handle_call/3 line 77 in context child_terminated

while send_request seems to do just fine.

[slezakattack]

I submitted a pull request on what has worked for me. Hope it helps.

#68

[lucacorti]

Thanks, but I think this is related to #57. APNS does not send END_STREAM or terminate connections, so I do not get responses.

[0chroma]

if I had to guess, the timeout stuff is happening because the chatterbox client is exiting with reason normal when apple sends a GOAWAY frame, which won't crash any linked processes if I understand correctly:

chatterbox/src/h2_connection.erl

Line 343 in d59b541

{stop, normal, Conn};

So you'll need to monitor the process or trap exits and handle them yourself I think (could be wrong)

[tsloughter]

Should be getting resolved in #127

Going to close this since it is 2 years old.