Skip to content

4.x: non-pooled connect ignores connect_timeout and exits the caller (the pool-less half of #927) #945

Description

@silverdr

hackney:connect_direct/4 calls hackney_conn:connect/1, which hardcodes an 8000 ms gen_statem:call deadline. The caller's connect_timeout reaches the connection process but not that outer call, so on the non-pooled path any connect_timeout above 8000 ms is capped at 8000 ms and expires as an exit in the caller rather than {error, _}.

This is the non-pooled half of #927, which was fixed for the pool only (hackney_pool:connect_connection/2 passes the timeout through and catches the exit). A commenter there raised the pool-less case; connect_direct/4 was never touched and still has both defects on master as of e494a51.

Environment

  • hackney 4.7.4, and master by inspection
  • Erlang/OTP 29 (erts 17.1)
  • Elixir 1.20.4
  • macOS 15.7.8

Reproduction

No stalled-transport stub needed; TEST-NET-1 blackholes the SYN.

Mix.install([{:hackney, "~> 4.7"}])

Application.ensure_all_started(:hackney)

defmodule Repro do
  # 192.0.2.1 is TEST-NET-1 (RFC 5737): routed nowhere, so the SYN is dropped
  # and the dial runs until some timer fires.
  @blackhole "https://192.0.2.1/"

  def run(label, opts) do
    started = System.monotonic_time(:millisecond)

    outcome =
      try do
        :hackney.request(:get, @blackhole, [], "", opts)
      catch
        :exit, reason -> {:caller_exit, reason}
      end

    IO.puts("#{label}: after #{System.monotonic_time(:millisecond) - started} ms -> #{inspect(outcome)}")
  end
end

:ok = :hackney_pool.start_pool(:repro_pool, max_connections: 1)

Repro.run("non-pooled, connect_timeout: 30000", pool: false, connect_timeout: 30_000)
Repro.run("non-pooled, connect_timeout:  2000", pool: false, connect_timeout: 2_000)
Repro.run("    pooled, connect_timeout: 15000", pool: :repro_pool, connect_timeout: 15_000)

Output:

non-pooled, connect_timeout: 30000: after 8016 ms -> {:caller_exit, {:timeout, {:gen_statem, :call, [#PID<0.511.0>, :connect, 8000]}}}
non-pooled, connect_timeout:  2000: after 2019 ms -> {:error, :timeout}
    pooled, connect_timeout: 15000: after 15002 ms -> {:error, :checkout_timeout}

Line 1 is the bug. Line 2 shows the connection process does honour connect_timeout whenever its own timer beats the hardcoded deadline. Line 3 shows the pooled path returning an error tuple.

Analysis

src/hackney.erl, connect_direct/4:

  ConnOpts = #{
    ...
    connect_timeout => proplists:get_value(connect_timeout, Options, 8000),
    ...
  },
  case hackney_conn_sup:start_conn(ConnOpts) of
    {ok, ConnPid} ->
      case hackney_conn:connect(ConnPid) of     %% <- connect/1

src/hackney_conn.erl:

-define(CONNECT_TIMEOUT, 8000).

connect(Pid) ->
    connect(Pid, ?CONNECT_TIMEOUT).             %% caller's value dropped

Every other call site passes a timeout explicitly (hackney_pool.erl:1047, hackney_h2_stream.erl:397, hackney.erl:315); hackney.erl:153 is the only one left on the defaulting arity.

So a caller that raised connect_timeout for a slow endpoint gets an unhandled exit instead of the error it configured for. For us it killed the GenServer that issued the request, and the crash report wrote that call's arguments to our error tracker in plain text.

Suggested fix

Symmetrical with the pool:

connect_direct(Transport, Host, Port, Options) ->
  ...
  ConnectTimeout = proplists:get_value(connect_timeout, Options, 8000),
  ConnOpts = #{
    ...
    connect_timeout => ConnectTimeout,
    ...
  },
  case hackney_conn_sup:start_conn(ConnOpts) of
    {ok, ConnPid} ->
      case connect_conn(ConnPid, ConnectTimeout) of
        ok ->
          {ok, ConnPid};
        {error, Reason} ->
          stop_conn(ConnPid),
          {error, Reason}
      end;
    {error, Reason} ->
      {error, Reason}
  end.

connect_conn(ConnPid, Timeout) ->
  try hackney_conn:connect(ConnPid, Timeout)
  catch
    exit:{timeout, _}                 -> {error, connect_timeout};
    exit:{Reason, {gen_statem, call, _}} -> {error, Reason};
    exit:Reason                       -> {error, Reason}
  end.

The try still matters once the timeout is passed through, for the same reason it does in hackney_pool:connect_connection/2: the outer deadline and the connection's own timer are set to the same value and race (19 ms of slack in line 2 above). connect_connection/2 is private to hackney_pool, so either lift it to a shared helper or duplicate it.

Two smaller things, happy to open them separately:

  • the reason atoms differ per path for the same fault: {error, timeout} non-pooled, {error, checkout_timeout} pooled, {error, connect_timeout} from connect_connection/2.
  • connect_tunnel/5 (SOCKS5/CONNECT) seeds connect_timeout into ConnOpts and returns the conn without dialling, so it looks unaffected, but I have not exercised it.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions