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.
hackney:connect_direct/4callshackney_conn:connect/1, which hardcodes an 8000 msgen_statem:calldeadline. The caller'sconnect_timeoutreaches the connection process but not that outer call, so on the non-pooled path anyconnect_timeoutabove 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/2passes the timeout through and catches the exit). A commenter there raised the pool-less case;connect_direct/4was never touched and still has both defects onmasteras of e494a51.Environment
masterby inspectionReproduction
No stalled-transport stub needed; TEST-NET-1 blackholes the SYN.
Output:
Line 1 is the bug. Line 2 shows the connection process does honour
connect_timeoutwhenever its own timer beats the hardcoded deadline. Line 3 shows the pooled path returning an error tuple.Analysis
src/hackney.erl,connect_direct/4:src/hackney_conn.erl:Every other call site passes a timeout explicitly (
hackney_pool.erl:1047,hackney_h2_stream.erl:397,hackney.erl:315);hackney.erl:153is the only one left on the defaulting arity.So a caller that raised
connect_timeoutfor a slow endpoint gets an unhandled exit instead of the error it configured for. For us it killed theGenServerthat 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:
The
trystill matters once the timeout is passed through, for the same reason it does inhackney_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/2is private tohackney_pool, so either lift it to a shared helper or duplicate it.Two smaller things, happy to open them separately:
{error, timeout}non-pooled,{error, checkout_timeout}pooled,{error, connect_timeout}fromconnect_connection/2.connect_tunnel/5(SOCKS5/CONNECT) seedsconnect_timeoutintoConnOptsand returns the conn without dialling, so it looks unaffected, but I have not exercised it.