unhandled `{ssl_closed, _}` message when using `async`

[paulswartz]

I see the following message in my Elixir logs periodically:

Unexpected message: {:ssl_closed, {:sslsocket, {:gen_tcp, #Port<0.9056>, :tls_connection, :undefined}, #PID<0.10027.10>}}

That looks like a close message from the SSL socket, which I'd expect hackney to manage the same as a close of the TCP connection (which are handled properly). I'm using the async option to stream the response data as it comes in.

[matthewoden]

I can reproduce this - I'm also using the async option with streaming. It seems that my chunk gets mixed in with it, as the last item in the tuple.

Unexpected message: {:ssl, {:sslsocket, {:gen_tcp, #Port<0.8780>, :tls_connection, :undefined}, #PID<0.380.0>}, <<250, 148, 222, 99, 116, 39, 82, 167, 182, 77, 245, 137, 189, 33, 60, 168, 182, 240, 30, 55, 235, 210, 208, 103, 217, 48, 245, 8, 29, 92, 27, 76, 134, 173, 101, 105, 228, 74, 31, 239, 5, 67, 94, 174, 203, 215, 11, 155, ...>>}

Update/Edit: When I run the streaming process in an Elixir Task, the message doesn't occur. Which makes me think there's a mailbox issue?

Only occurs in our deployment environment, (cloudfoundry, ubuntu trusty). Locally on OSX 10.12.5, there's no issue.

Using hackney 1.11

code snippet:

   # options for request - [async: :once, stream_to: self()]

    defp handle_async(%{status: status} = conn, ref) do
        :ok = :hackney.stream_next(ref)

        receive do
            {:hackney_response, ^ref, {:status, code, _reason}} ->
                conn
                |> Plug.Conn.put_status(code)
                |> handle_async(ref)

            {:hackney_response, ^ref, {:headers, headers, }} ->
                downcased_headers =
                    headers
                    |> Stream.map(fn {k,v} -> {String.downcase(k), v} end)
                    |> Enum.filter(fn {k, _v} -> k !== "cache-control" end)

                conn
                |> Plug.Conn.merge_resp_headers(downcased_headers)
                |> Plug.Conn.delete_resp_header("content-length") #RFC spec dictates no content-length on chunked requests
                |> Plug.Conn.put_resp_header("connection", "close")
                |> Plug.Conn.send_chunked(status)
                |> handle_async(ref)

            {:hackney_response, ^ref, :done} ->
                conn

            {:hackney_response, ^ref, chunk} ->
                case Plug.Conn.chunk(conn, chunk) do
                    {:ok, new_conn} ->
                        handle_async(new_conn, ref)

                    {:error, :closed} ->
                        Logger.info("Client canceled request.")
                        :hackney.close(ref)
                        conn

                    {:error, reason } ->
                        Logger.error("Unable to complete request: #{inspect(reason)}")
                        :hackney.close(ref)
                        conn
                end

            message ->
                Logger.warn("Hackney.handle_async got an unexpected message: #{inspect(message)}")
                handle_async(conn, ref)
       end
    end

[benoitc]

hrm it's probably happening on close. @paulswartz is your code similar to the one posted by @matthewoden ?

[paulswartz]

I'm using hackney via httpoison, but here's the relevant code: https://github.com/edgurgel/httpoison/blob/master/lib/httpoison/base.ex#L369-L387

[matthewoden]

If it matters, I've done a quick port on my code over to :ibrowse, and the issue hasn't come up again. The receive block is basically the same (though ibrowse combines status and headers into a single message).

I'd prefer to use hackney, so just let me know if you need any other usage info.

[benoitc]

well the issue is that a message is still on the process heap after cloising the socket. I have a fix for it. Will take care of it later today. Thanks for the code!