Unexpected unwrapped return %Mint.TransportError{reason: :closed} from Mint.HTTP1.connect/4

[jozuas]

• Req version: 0.5.1
• Finch version: 0.18.0
• Mint version: 1.6.1
• Elixir version: 1.15.7
• OTP version: Erlang/OTP 26 [erts-14.2.5]

I observed the following in my application logs:

** (CaseClauseError) no case clause matching: %Mint.TransportError{reason: :closed}
(finch 0.18.0) lib/finch/http1/conn.ex:52: Finch.HTTP1.Conn.connect/2
(finch 0.18.0) lib/finch/http1/pool.ex:58: anonymous fn/10 in Finch.HTTP1.Pool.request/6
(nimble_pool 1.1.0) lib/nimble_pool.ex:462: NimblePool.checkout!/4
(finch 0.18.0) lib/finch/http1/pool.ex:52: Finch.HTTP1.Pool.request/6
(finch 0.18.0) lib/finch.ex:472: anonymous fn/4 in Finch.request/3
(telemetry 1.2.1) /opt/terrapin-app/deps/telemetry/src/telemetry.erl:321: :telemetry.span/3
(req 0.5.1) lib/req/steps.ex:977: Req.Steps.run_finch_request/3
(req 0.5.1) lib/req/steps.ex:809: Req.Steps.run_finch/4

lib/finch/http1/conn.ex:52:

    case Mint.HTTP.connect(conn.scheme, conn.host, conn.port, conn_opts) do
      {:ok, mint} ->
        Telemetry.stop(:connect, start_time, meta)
        SSL.maybe_log_secrets(conn.scheme, conn_opts, mint)
        {:ok, %{conn | mint: mint}}

      {:error, error} ->
        meta = Map.put(meta, :error, error)
        Telemetry.stop(:connect, start_time, meta)
        {:error, conn, error}
    end

Mint.HTTP1.connect/4 return type should be:

  @spec connect(Types.scheme(), Types.address(), :inet.port_number(), keyword()) ::
          {:ok, t()} | {:error, Types.error()}

Not sure how to replicate given that this for me is a transient issue

[wojtekmach]

seems like a Finch bug, could you move this issue to Finch repo? nevermind

[wojtekmach]

Can you share which URL you hit? Is it over http or https? ipv4, ipv6? Any extra context would really help.

[jozuas]

Looking at my logs further I've discovered another unexpected unwrapped return from Min.HTTP1.connect/4, a nested Mint.TransportError, which seems like a related bug:

** (CaseClauseError) no case clause matching: %Mint.TransportError{reason: %Mint.TransportError{reason: :timeout}}
(finch 0.18.0) lib/finch/http1/conn.ex:52: Finch.HTTP1.Conn.connect/2
(finch 0.18.0) lib/finch/http1/pool.ex:58: anonymous fn/10 in Finch.HTTP1.Pool.request/6
(nimble_pool 1.1.0) lib/nimble_pool.ex:462: NimblePool.checkout!/4
(finch 0.18.0) lib/finch/http1/pool.ex:52: Finch.HTTP1.Pool.request/6
(finch 0.18.0) lib/finch.ex:472: anonymous fn/4 in Finch.request/3
(telemetry 1.2.1) /opt/terrapin-app/deps/telemetry/src/telemetry.erl:321: :telemetry.span/3
(req 0.5.0) lib/req/steps.ex:953: Req.Steps.run_finch_request/3
(req 0.5.0) lib/req/steps.ex:785: Req.Steps.run_finch/4

[jozuas]

Can you share which URL you hit? Is it over http or https? ipv4, ipv6? Any extra context would really help.

I am making Req requests through a pool of proxies.

It looks roughly like:

  @spec base_req() :: Req.Request.t()
  def base_req() do
    proxy = Tp.Proxy.rotate()

    Req.new(
      base_url: "https://...",
      connect_options: [
        proxy: {:http, proxy.ip, proxy.port, []},
        proxy_headers: [{"Proxy-Authorization", "Basic: #{Base.encode64(proxy.userpass)}"}]
      ]
    )
  end

We have around 10 proxies. They are quite unreliable. We get intermittent HTTP 407, :timeout, :ehostunreach, etc. from the proxies.

The connection path is over IPv4, and looks like this:

machine in my control -> http -> proxy -> https -> url

[whatyouhide]

%Mint.TransportError{reason: %Mint.TransportError{reason: :timeout}}

This is definitely an error yeah. I'll try to take a look.

[jozuas]

@whatyouhide any updates 🙂?

[whatyouhide]

@jozuas no, didn't have time to look at this. Want to give it a try? Usually we call functions like wrap_error and we must be calling it on an already-wrapped error here. The way I usually debug this is with a bunch of dbg calls around, in this case maybe in Mint.TunnelProxy or Mint.UnsafeProxy given it seems to be happening around proxying 🙃

[jozuas]

I think I will:

1. Fork the project
2. Add some extra diagnostics
3. Run in prod, and see what information I can capture

Let's see what turns up.

[whatyouhide]

@jozuas sounds fantastic, thank you.

[jozuas]

I'm looking at my AppSignal error tracker, and I see that the last time I had an exception for this was 17 days ago, it's probably faster to look at the code 😅

[jozuas]

Ah, well, here we go:

Follow upgrade_connection/3:

mint/lib/mint/tunnel_proxy.ex

Lines 8 to 14 in 63ce63c

	@spec connect(tuple(), tuple()) :: {:ok, Mint.HTTP.t()} | {:error, term()}
	def connect(proxy, host) do
	case establish_proxy(proxy, host) do
	{:ok, conn} -> upgrade_connection(conn, proxy, host)
	{:error, reason} -> {:error, reason}
	end
	end

Follow wrap_in_proxy_error/1:

mint/lib/mint/tunnel_proxy.ex

Lines 39 to 52 in 63ce63c

	defp upgrade_connection(
	conn,
	{proxy_scheme, _proxy_address, _proxy_port, _proxy_opts} = _proxy,
	{scheme, hostname, port, opts} = _host
	) do
	proxy_headers = HTTP1.get_proxy_headers(conn)
	socket = HTTP1.get_socket(conn)
	# Note that we may leak messages if the server sent data after the CONNECT response
	case Negotiate.upgrade(proxy_scheme, socket, scheme, hostname, port, opts) do
	{:ok, conn} -> {:ok, HTTP.put_proxy_headers(conn, proxy_headers)}
	{:error, reason} -> wrap_in_proxy_error(reason)
	end
	end

mint/lib/mint/tunnel_proxy.ex

Lines 119 to 129 in 63ce63c

	defp wrap_in_proxy_error(%HTTPError{reason: {:proxy, _}} = error) do
	error
	end
	defp wrap_in_proxy_error(%HTTPError{reason: reason}) do
	%HTTPError{module: __MODULE__, reason: {:proxy, reason}}
	end
	defp wrap_in_proxy_error(%TransportError{} = error) do
	error
	end

And so the real return of upgrade_connection/3 is:

{:ok, ...} | %HTTPError{}

Instead of

{:ok, ...} | {:error, %HTTPError{}}