diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index 616e98cd..7359020a 100644 --- a/DEVELOPMENT.md +++ b/DEVELOPMENT.md @@ -66,6 +66,64 @@ gunicorn -b 127.0.0.1:8000 httpbin:app & rebar3 eunit ``` +### Fault injection and chaos tests + +Use these when you change the pool or the connection state machine. Ordinary +integration tests only exercise servers that answer, so they never see a +connection that stalls, crashes, or dies at the wrong moment, which is where +pool failures come from: the pool dials and stops connections from inside its +own gen_server, and an unguarded call that exits takes the pool down along with +every caller using it. + +Three pieces make up the harness: + +| Module | What it does | +| --- | --- | +| `hackney_fault_transport` | A transport that behaves like `hackney_tcp` until you arm a fault on one of its callbacks | +| `hackney_crash_sentinel` | Captures crash reports so a test can assert a process survived, even with `error_logger:tty(false)` | +| `hackney_pool_safety_tests` | Walks the compiled abstract code and fails on any call into `hackney_conn` that is not inside a `try` | + +Arm a fault, drive the code path, assert the pool is untouched: + +```erlang +ok = hackney_crash_sentinel:start(), +hackney_fault_transport:set(connect, {slow_error, 300}), +Opts = [{pool, my_pool}, {connect_timeout, 30}], +{error, connect_timeout} = + hackney_pool:checkout("127.0.0.1", 8080, hackney_fault_transport, Opts), +hackney_crash_sentinel:assert_no_crash_from(hackney_pool:find_pool(my_pool)), +ok = hackney_fault_transport:clear(). +``` + +Available faults: `{sleep, Ms}`, `{slow_error, Ms}`, `{hang, Ms}`, `{error, Reason}`, +`crash`. Any callback can be armed: `connect`, `send`, `recv`, `setopts`, +`close`, `controlling_process`. + +Run the fault matrix, the multiplexed (HTTP/2, HTTP/3) checkout faults, and the +randomized chaos run: + +```bash +rebar3 eunit --module=hackney_pool_fault_tests +rebar3 eunit --module=hackney_pool_h2h3_fault_tests +rebar3 eunit --module=hackney_pool_chaos_tests +``` + +The HTTP/2 and HTTP/3 connections are shared rather than checked out, so one +bad connection is felt by every caller for that host. Those scenarios wedge a +registered connection with `sys:suspend/1` and require the pool to answer +`none` within the probe budget instead of waiting on it. + +Soak the chaos run harder, for example before a release: + +```bash +HACKNEY_CHAOS_WORKERS=64 HACKNEY_CHAOS_ROUNDS=2000 \ + rebar3 eunit --module=hackney_pool_chaos_tests +``` + +If `hackney_pool_safety_tests` fails, route the new call through a guarded +helper in `hackney_pool` (`connect_connection/2`, `set_owner/2`, `stop_conn/1`, +`checkin_info/1`) rather than relaxing the check. + ## Local Docker Testing A Dockerfile is provided for testing on Linux locally, which mirrors the GitHub CI environment. diff --git a/src/hackney_conn.erl b/src/hackney_conn.erl index 57d21e47..73ec3243 100644 --- a/src/hackney_conn.erl +++ b/src/hackney_conn.erl @@ -26,9 +26,11 @@ -export([ start_link/1, stop/1, + stop/2, connect/1, connect/2, get_state/1, + get_state/2, %% Request/Response (sync) request/5, request/6, @@ -72,6 +74,7 @@ release_to_pool/1, verify_socket/1, is_ready/1, + is_ready/2, %% SSL upgrade upgrade_to_ssl/2, upgrade_to_ssl/3, @@ -79,8 +82,10 @@ %% Reuse control is_no_reuse/1, checkin_info/1, + checkin_info/2, %% Owner management set_owner/2, + set_owner/3, set_owner_async/2, %% Protocol info get_protocol/1 @@ -270,15 +275,31 @@ start_link(Opts) when is_map(Opts) -> %% Returns ok even if the process has already terminated. -spec stop(pid()) -> ok. stop(Pid) -> + stop(Pid, infinity). + +%% @doc Stop the connection process, waiting at most `Timeout' for it. +%% A connection wedged inside a transport call (a dial that outlived its +%% timeout, a socket that never answers) cannot handle a stop request; it is +%% killed rather than left holding the caller, which for pool checkouts is the +%% pool gen_server itself. +%% Returns ok even if the process has already terminated. +-spec stop(pid(), timeout()) -> ok. +stop(Pid, Timeout) -> try - gen_statem:stop(Pid) + gen_statem:stop(Pid, normal, Timeout) catch exit:noproc -> ok; exit:{noproc, _} -> ok; exit:normal -> ok; - exit:{normal, _} -> ok + exit:{normal, _} -> ok; + exit:timeout -> kill(Pid); + exit:{timeout, _} -> kill(Pid) end. +kill(Pid) -> + exit(Pid, kill), + ok. + %% @doc Connect to the target host. Blocks until connected or timeout. -spec connect(pid()) -> ok | {error, term()}. connect(Pid) -> @@ -291,7 +312,15 @@ connect(Pid, Timeout) -> %% @doc Get current state name for debugging. -spec get_state(pid()) -> {ok, atom()} | {error, term()}. get_state(Pid) -> - gen_statem:call(Pid, get_state). + get_state(Pid, 5000). + +%% @doc Get current state name, waiting at most `Timeout'. Callers that probe +%% a connection they do not own (the pool, deciding whether to hand it out) +%% pass a short timeout: a connection that cannot answer promptly is unusable +%% to them, and waiting on it blocks everything behind them. +-spec get_state(pid(), timeout()) -> {ok, atom()} | {error, term()}. +get_state(Pid, Timeout) -> + gen_statem:call(Pid, get_state, Timeout). %% @doc Send an HTTP request and wait for the response status and headers. %% Returns {ok, Status, Headers} for HTTP/1.1 or {ok, Status, Headers, Body} for HTTP/2. @@ -571,7 +600,12 @@ release_to_pool(Pid) -> %% a connection to a new requester. -spec set_owner(pid(), pid()) -> ok | {error, invalid_state}. set_owner(Pid, NewOwner) -> - gen_statem:call(Pid, {set_owner, NewOwner}, 5000). + set_owner(Pid, NewOwner, 5000). + +%% @doc Set a new owner, waiting at most `Timeout'. @see get_state/2 +-spec set_owner(pid(), pid(), timeout()) -> ok | {error, invalid_state}. +set_owner(Pid, NewOwner, Timeout) -> + gen_statem:call(Pid, {set_owner, NewOwner}, Timeout). %% @doc Set a new owner for this connection (async). %% Same as set_owner/2 but non-blocking. Used when the caller cannot @@ -591,7 +625,12 @@ verify_socket(Pid) -> %% This combines state check and socket verification in one call. -spec is_ready(pid()) -> {ok, connected} | {ok, closed} | {error, term()}. is_ready(Pid) -> - gen_statem:call(Pid, is_ready). + is_ready(Pid, 5000). + +%% @doc Check socket health, waiting at most `Timeout'. @see get_state/2 +-spec is_ready(pid(), timeout()) -> {ok, connected} | {ok, closed} | {error, term()}. +is_ready(Pid, Timeout) -> + gen_statem:call(Pid, is_ready, Timeout). %% @doc Upgrade a TCP connection to SSL. %% This performs an SSL handshake on the existing TCP socket. @@ -632,7 +671,12 @@ is_no_reuse(Pid) -> pool_ssl := boolean(), protocol := atom(), should_close := boolean(), ready := boolean()}. checkin_info(Pid) -> - gen_statem:call(Pid, checkin_info). + checkin_info(Pid, 5000). + +%% @doc Checkin flags, waiting at most `Timeout'. @see get_state/2 +-spec checkin_info(pid(), timeout()) -> map(). +checkin_info(Pid, Timeout) -> + gen_statem:call(Pid, checkin_info, Timeout). %% @doc Get the negotiated protocol for this connection. %% Returns http1, http2, or http3 based on ALPN negotiation (SSL connections), diff --git a/src/hackney_conn_sup.erl b/src/hackney_conn_sup.erl index 0d1ef8e6..5347c2b9 100644 --- a/src/hackney_conn_sup.erl +++ b/src/hackney_conn_sup.erl @@ -41,9 +41,11 @@ start_conn(Opts) -> supervisor:start_child(?SERVER, [Opts]). %% @doc Stop a connection process gracefully. +%% Tolerates a connection that is already gone or that dies while stopping: +%% callers are only asking for it to be off. -spec stop_conn(pid()) -> ok. stop_conn(Pid) -> - hackney_conn:stop(Pid). + try hackney_conn:stop(Pid) catch _:_ -> ok end. %% @doc Stop all connection processes gracefully. %% Useful for test cleanup. diff --git a/src/hackney_pool.erl b/src/hackney_pool.erl index d96e07a0..b48ce0bc 100644 --- a/src/hackney_pool.erl +++ b/src/hackney_pool.erl @@ -92,6 +92,13 @@ -define(DEFAULT_MAX_CONNECTIONS, 50). -define(DEFAULT_KEEPALIVE_TIMEOUT, 2000). % 2 seconds max idle -define(DEFAULT_PREWARM_COUNT, 4). % Connections to maintain per host +-define(STOP_CONN_TIMEOUT, 100). % Max wait for a conn to stop +-define(PREWARM_CONNECT_TIMEOUT, 5000). % Dial budget for a prewarm conn +%% Every question the pool asks a conn about its own health is answered from +%% the conn's state, so a healthy conn answers at once. A conn that does not +%% is wedged, and waiting on it from inside the pool gen_server blocks every +%% caller of the pool, not just the one that asked: treat slow as unusable. +-define(PROBE_TIMEOUT, 250). start() -> %% Create ETS table to store pool pid by name @@ -544,7 +551,7 @@ handle_call({checkout, Key, Requester, Opts}, _From, State) -> {ok, Pid, Available2} -> %% Found an available connection - update owner to new requester ?report_debug("pool: reusing connection", [{pool, PoolName}, {pid, Pid}]), - case hackney_conn:set_owner(Pid, Requester) of + case set_owner(Pid, Requester) of ok -> InUse2 = maps:put(Pid, Key, InUse), {reply, {ok, Pid}, State#state{available=Available2, in_use=InUse2}}; @@ -589,7 +596,7 @@ handle_call({checkout_ssl, SslKey, Requester, Opts}, _From, State) -> {ok, Pid, Available2} -> %% Found a pooled SSL connection with the same TLS options hash ?report_debug("pool: reusing ssl connection", [{pool, PoolName}, {pid, Pid}]), - case hackney_conn:set_owner(Pid, Requester) of + case set_owner(Pid, Requester) of ok -> InUse2 = maps:put(Pid, SslKey, InUse), {reply, {ok, Pid, ready}, @@ -889,9 +896,13 @@ h3_connection_key(Host0, Port, Transport, Options) -> Host = string:lowercase(Host0), {Host, Port, Transport, proplists:get_value(h3_tls_key, Options, default)}. -%% @private Stop a connection, tolerating an already-dead process. +%% @private Stop a connection, tolerating an already-dead process. Bounded on +%% purpose: this runs inside the pool gen_server, and a conn wedged in a +%% transport call (the dial that just outlived its timeout, typically) would +%% otherwise hold every caller of the pool for as long as the transport takes +%% to return. Past the deadline the conn is killed. stop_conn(Pid) -> - try hackney_conn:stop(Pid) catch _:_ -> ok end. + try hackney_conn:stop(Pid, ?STOP_CONN_TIMEOUT) catch _:_ -> ok end. %% @private Find a reusable idle connection for `Key', discarding any that are %% no longer keepalive-ready. Only a conn that is_ready reports `{ok, connected}' @@ -912,7 +923,7 @@ find_available(Key, Available) -> %% The connection can die between is_process_alive/1 above %% and this gen_statem call (flaky network); the resulting %% noproc exit must not crash the pool, so skip and move on. - try hackney_conn:is_ready(Pid) of + try hackney_conn:is_ready(Pid, ?PROBE_TIMEOUT) of {ok, connected} -> {ok, Pid, Available2}; _ -> @@ -952,7 +963,7 @@ checkout_ssl_fallback(SslKey, Requester, Opts, State) -> case find_available(TcpKey, Available) of {ok, Pid, Available2} -> - case hackney_conn:set_owner(Pid, Requester) of + case set_owner(Pid, Requester) of ok -> InUse2 = maps:put(Pid, SslKey, InUse), {reply, {ok, Pid, needs_upgrade}, @@ -1014,7 +1025,7 @@ start_connection(Host, Port, Transport, Owner, Opts, State) -> case hackney_conn_sup:start_conn(ConnOpts) of {ok, Pid} -> %% Connect the connection - case hackney_conn:connect(Pid) of + case connect_connection(Pid, ConnectTimeout) of ok -> %% Monitor the process MonRef = erlang:monitor(process, Pid), @@ -1028,6 +1039,23 @@ start_connection(Host, Port, Transport, Owner, Opts, State) -> {error, Reason} end. +%% @private Convert a failed connection call into a checkout error. The pool +%% must not terminate because a DNS/TCP/TLS attempt outlives its timeout, nor +%% because the connection process dies while dialing (a transport raising, or +%% the conn being killed). The caller stops the conn on any error return. +connect_connection(Pid, Timeout) -> + try hackney_conn:connect(Pid, Timeout) of + Result -> + Result + catch + exit:{timeout, _} -> + {error, connect_timeout}; + exit:{Reason, {gen_statem, call, _}} -> + {error, Reason}; + exit:Reason -> + {error, Reason} + end. + %% @private Process a checkin - return connection to pool. %% Plain TCP connections are stored under their TCP key. An SSL upgraded %% connection is stored only when it was checked out through checkout_ssl @@ -1088,11 +1116,21 @@ checkin_poolable(_TcpKey, Info) -> maps:get(upgraded_ssl, Info, false) =:= false andalso keepalive_ready(Info). +%% @private Hand a pooled conn to its new owner. Called from inside the pool +%% gen_server, so it must not raise: the conn answered `is_ready' a moment ago +%% but can be gone or wedged by now, and either would take the pool down. Any +%% failure means the conn is unusable; every caller already dials a fresh one +%% on `{error, _}'. +set_owner(Pid, Owner) -> + try hackney_conn:set_owner(Pid, Owner, ?PROBE_TIMEOUT) + catch _:_ -> {error, set_owner_failed} + end. + %% @private Fetch the conn's checkin flags, or `error' if the call fails (the %% conn died between is_process_alive/1 and here). Caller treats `error' as %% not poolable. checkin_info(Pid) -> - try {ok, hackney_conn:checkin_info(Pid)} + try {ok, hackney_conn:checkin_info(Pid, ?PROBE_TIMEOUT)} catch _:_ -> error end. @@ -1205,7 +1243,7 @@ h2_conn_usable(Pid) -> case erlang:is_process_alive(Pid) of false -> false; true -> - try hackney_conn:get_state(Pid) of + try hackney_conn:get_state(Pid, ?PROBE_TIMEOUT) of {ok, connected} -> true; _ -> false catch @@ -1333,7 +1371,7 @@ prewarm_connections(PoolPid, Host, Port, Count, IdleTimeout) -> }, case hackney_conn_sup:start_conn(ConnOpts) of {ok, Pid} -> - case hackney_conn:connect(Pid) of + case connect_connection(Pid, ?PREWARM_CONNECT_TIMEOUT) of ok -> %% Checkin the new connection to the pool gen_server:cast(PoolPid, {prewarm_checkin, Pid, diff --git a/test/hackney_crash_sentinel.erl b/test/hackney_crash_sentinel.erl new file mode 100644 index 00000000..da94835b --- /dev/null +++ b/test/hackney_crash_sentinel.erl @@ -0,0 +1,144 @@ +%%% -*- erlang -*- +%%% +%%% This file is part of hackney released under the Apache 2 license. +%%% See the NOTICE for more information. +%%% +%%% @doc Test helper: capture process crash reports so a test can assert none +%%% happened. +%%% +%%% The integration suites call `error_logger:tty(false)' to keep expected +%%% failures out of the test output, which also hides unexpected ones: a pool +%%% gen_server dying mid-test leaves no trace beyond a confusing follow-on +%%% failure (issue #927 was exactly that). Install the sentinel around a +%%% scenario and assert on what it collected: +%%% +%%% ``` +%%% ok = hackney_crash_sentinel:start(), +%%% ... run the scenario ... +%%% hackney_crash_sentinel:assert_no_crash_from(PoolPid), +%%% ok = hackney_crash_sentinel:stop(). +%%% ''' +-module(hackney_crash_sentinel). + +-export([start/0, stop/0, clear/0, reports/0, reports_from/1, + assert_no_crash/0, assert_no_crash_from/1]). + +%% logger handler callback +-export([log/2]). + +-define(NAME, ?MODULE). +-define(CALL_TIMEOUT, 5000). + +%%==================================================================== +%% API +%%==================================================================== + +%% @doc Start collecting crash reports. Idempotent. +start() -> + _ = stop(), + Self = self(), + Pid = spawn(fun() -> Self ! {?NAME, started}, collect([]) end), + true = register(?NAME, Pid), + receive {?NAME, started} -> ok after ?CALL_TIMEOUT -> ok end, + ok = logger:add_handler(?NAME, ?MODULE, #{level => error}), + ok. + +%% @doc Stop collecting and drop everything collected. Safe to call twice. +stop() -> + _ = logger:remove_handler(?NAME), + case whereis(?NAME) of + undefined -> ok; + Pid -> Pid ! stop, ok + end. + +%% @doc Drop everything collected so far, keep collecting. +clear() -> + call(clear). + +%% @doc Every crash report collected so far, oldest first. +reports() -> + call(reports). + +%% @doc Crash reports emitted by `Pid'. +reports_from(Pid) -> + [R || R <- reports(), maps:get(pid, R, undefined) =:= Pid]. + +%% @doc Fail unless no process crashed since `start/0' or the last `clear/0'. +assert_no_crash() -> + assert_empty(reports()). + +%% @doc Fail unless `Pid' survived. Use this when the scenario crashes other +%% processes on purpose (a connection, a request owner) but one process is +%% expected to stay up. +assert_no_crash_from(Pid) -> + assert_empty(reports_from(Pid)). + +%%==================================================================== +%% logger handler +%%==================================================================== + +%% Runs in the caller's process: never raise, never log. +log(#{level := Level, msg := Msg, meta := Meta}, _Config) -> + case crash(Msg) of + {true, Label, Reason} -> + Report = #{label => Label, + reason => Reason, + level => Level, + pid => maps:get(pid, Meta, undefined)}, + _ = (try ?NAME ! {report, Report} catch _:_ -> ok end), + ok; + false -> + ok + end; +log(_Event, _Config) -> + ok. + +%% Only abnormal terminations count. A `normal' or `shutdown' stop is how the +%% suites tear pools and connections down. +crash({report, #{label := {_, terminate} = Label, reason := Reason}}) -> + abnormal(Label, Reason); +crash({report, #{label := {proc_lib, crash} = Label} = R}) -> + abnormal(Label, maps:get(report, R, unknown)); +crash({report, #{label := {supervisor, child_terminated} = Label} = R}) -> + abnormal(Label, maps:get(report, R, unknown)); +crash({report, #{label := {supervisor, start_error} = Label} = R}) -> + abnormal(Label, maps:get(report, R, unknown)); +crash(_) -> + false. + +abnormal(_Label, normal) -> false; +abnormal(_Label, shutdown) -> false; +abnormal(_Label, {shutdown, _}) -> false; +abnormal(Label, Reason) -> {true, Label, Reason}. + +%%==================================================================== +%% Internal +%%==================================================================== + +collect(Acc) -> + receive + {report, Report} -> + collect([Report | Acc]); + {reports, From} -> + From ! {?NAME, lists:reverse(Acc)}, + collect(Acc); + {clear, From} -> + From ! {?NAME, []}, + collect([]); + stop -> + ok + end. + +call(Op) -> + case whereis(?NAME) of + undefined -> + []; + Pid -> + Pid ! {Op, self()}, + receive {?NAME, Reply} -> Reply after ?CALL_TIMEOUT -> [] end + end. + +assert_empty([]) -> + ok; +assert_empty(Reports) -> + erlang:error({unexpected_crash, Reports}). diff --git a/test/hackney_fault_transport.erl b/test/hackney_fault_transport.erl new file mode 100644 index 00000000..9287bc13 --- /dev/null +++ b/test/hackney_fault_transport.erl @@ -0,0 +1,197 @@ +%%% -*- erlang -*- +%%% +%%% This file is part of hackney released under the Apache 2 license. +%%% See the NOTICE for more information. +%%% +%%% @doc Test transport that behaves exactly like {@link hackney_tcp} until it +%%% is told to misbehave. +%%% +%%% Pass it as the `Transport' of a pool checkout (or as `transport' in +%%% connection options) and arm a fault per callback: +%%% +%%% ``` +%%% hackney_fault_transport:set(connect, {slow_error, 200}), %% issue #927 +%%% hackney_fault_transport:set(send, crash), +%%% hackney_fault_transport:clear(). +%%% ''' +%%% +%%% Unarmed callbacks delegate to `hackney_tcp', so a connection dialled +%%% through this module talks to a real server and can carry real requests. +%%% That is what makes the faults interesting: they land in the middle of the +%%% ordinary code path rather than in a stub. +%%% +%%% Faults: +%%% +-module(hackney_fault_transport). + +%% Fault control +-export([set/1, set/2, clear/0, clear/1, calls/1]). + +%% hackney transport callbacks +-export([messages/1, + connect/3, connect/4, + recv/2, recv/3, + send/2, + setopts/2, + controlling_process/2, + peername/1, + close/1, + shutdown/2, + sockname/1]). + +-define(TABLE, hackney_fault_transport_faults). +-define(OWNER, hackney_fault_transport_owner). + +-type fault() :: ok + | {sleep, non_neg_integer()} + | {slow_error, non_neg_integer()} + | {hang, non_neg_integer()} + | {error, term()} + | crash. + +-export_type([fault/0]). + +%%==================================================================== +%% Fault control +%%==================================================================== + +%% @doc Arm `Fault' on connect/4, the callback most scenarios care about. +-spec set(fault()) -> ok. +set(Fault) -> set(connect, Fault). + +%% @doc Arm `Fault' on one callback (`connect', `send', `recv', `setopts', +%% `close', `controlling_process'). +-spec set(atom(), fault()) -> ok. +set(Callback, Fault) -> + ensure_table(), + true = ets:insert(?TABLE, {{fault, Callback}, Fault}), + ok. + +%% @doc Disarm every callback. Call counters survive: a test that clears +%% faults before reporting still wants to know what ran. +-spec clear() -> ok. +clear() -> + ensure_table(), + true = ets:match_delete(?TABLE, {{fault, '_'}, '_'}), + ok. + +%% @doc Disarm one callback. +-spec clear(atom()) -> ok. +clear(Callback) -> + ensure_table(), + true = ets:delete(?TABLE, {fault, Callback}), + ok. + +%% @doc How many times a callback ran since the table was created. Lets a test +%% prove it exercised the path it thinks it did: a chaos run that never dials +%% is not testing connect faults, however many faults it armed. +-spec calls(atom()) -> non_neg_integer(). +calls(Callback) -> + try ets:lookup(?TABLE, {calls, Callback}) of + [{_, N}] -> N; + [] -> 0 + catch + error:badarg -> 0 + end. + +%%==================================================================== +%% Transport callbacks +%%==================================================================== + +messages(Socket) -> hackney_tcp:messages(Socket). + +connect(Host, Port, Opts) -> connect(Host, Port, Opts, infinity). + +connect(Host, Port, Opts, Timeout) -> + with_fault(connect, fun() -> hackney_tcp:connect(Host, Port, Opts, Timeout) end). + +recv(Socket, Length) -> recv(Socket, Length, infinity). + +recv(Socket, Length, Timeout) -> + with_fault(recv, fun() -> hackney_tcp:recv(Socket, Length, Timeout) end). + +send(Socket, Packet) -> + with_fault(send, fun() -> hackney_tcp:send(Socket, Packet) end). + +setopts(Socket, Opts) -> + with_fault(setopts, fun() -> hackney_tcp:setopts(Socket, Opts) end). + +controlling_process(Socket, Pid) -> + with_fault(controlling_process, + fun() -> hackney_tcp:controlling_process(Socket, Pid) end). + +close(Socket) -> + with_fault(close, fun() -> hackney_tcp:close(Socket) end). + +peername(Socket) -> hackney_tcp:peername(Socket). + +sockname(Socket) -> hackney_tcp:sockname(Socket). + +shutdown(Socket, How) -> hackney_tcp:shutdown(Socket, How). + +%%==================================================================== +%% Internal +%%==================================================================== + +with_fault(Callback, Delegate) -> + count(Callback), + case fault(Callback) of + ok -> + Delegate(); + {sleep, Ms} -> + timer:sleep(Ms), + Delegate(); + {slow_error, Ms} -> + timer:sleep(Ms), + {error, simulated_timeout}; + {hang, Ms} -> + timer:sleep(Ms), + {error, simulated_hang}; + {error, Reason} -> + {error, Reason}; + crash -> + erlang:error({simulated_crash, Callback}) + end. + +count(Callback) -> + try ets:update_counter(?TABLE, {calls, Callback}, 1, {{calls, Callback}, 0}) of + _ -> ok + catch + error:badarg -> ok + end. + +fault(Callback) -> + try ets:lookup(?TABLE, {fault, Callback}) of + [{_, Fault}] -> Fault; + [] -> ok + catch + error:badarg -> ok + end. + +%% The table outlives the eunit process that armed it: each test runs in a +%% fresh process, and connection processes read faults after it has exited. +ensure_table() -> + case ets:whereis(?TABLE) of + undefined -> start_owner(); + _Tid -> ok + end. + +start_owner() -> + Self = self(), + _ = spawn(fun() -> + _ = (try ets:new(?TABLE, [named_table, public, set]) catch _:_ -> ok end), + _ = (try register(?OWNER, self()) catch _:_ -> ok end), + Self ! {?MODULE, ready}, + receive stop -> ok end + end), + receive {?MODULE, ready} -> ok after 5000 -> ok end, + ok. diff --git a/test/hackney_pool_chaos_tests.erl b/test/hackney_pool_chaos_tests.erl new file mode 100644 index 00000000..3d395452 --- /dev/null +++ b/test/hackney_pool_chaos_tests.erl @@ -0,0 +1,292 @@ +%%% -*- erlang -*- +%%% +%%% This file is part of hackney released under the Apache 2 license. +%%% See the NOTICE for more information. +%%% +%%% @doc Randomized pool chaos: real requests against a real server while the +%%% transport misbehaves underneath and callers die at the wrong moment. +%%% +%%% {@link hackney_pool_fault_tests} pins one fault at a time. This one runs +%%% them concurrently and in unpredictable order, which is where the +%%% interesting failures live: a fault arriving between two steps of a checkout, +%%% a connection dying while another caller is queued behind it, a caller +%%% vanishing mid-request. The assertions are not about any single request +%%% succeeding - under injected faults many will not - but about what must hold +%%% once the storm passes: +%%% +%%% +%%% +%%% Scale it up for a soak run: +%%% +%%% ``` +%%% HACKNEY_CHAOS_WORKERS=64 HACKNEY_CHAOS_ROUNDS=200 rebar3 eunit \ +%%% --module=hackney_pool_chaos_tests +%%% ''' +%%% +%%% Every worker seeds its own generator from `HACKNEY_CHAOS_SEED' (default 42) +%%% so a failing run can be replayed with the seed printed in the output. +-module(hackney_pool_chaos_tests). + +-include_lib("eunit/include/eunit.hrl"). + +-define(POOL, chaos_test_pool). +-define(HOST, "127.0.0.1"). +-define(PORT, 8142). + +%%==================================================================== +%% Fixture +%%==================================================================== + +chaos_test_() -> + {setup, + fun setup/0, + fun teardown/1, + [{"the pool survives a randomized fault storm and serves again", + {timeout, 300, fun t_chaos/0}}]}. + +setup() -> + error_logger:tty(false), + {ok, _} = application:ensure_all_started(cowboy), + {ok, _} = application:ensure_all_started(hackney), + Dispatch = cowboy_router:compile([{'_', [{"/[...]", test_http_resource, []}]}]), + {ok, _} = cowboy:start_clear(chaos_test_server, [{port, ?PORT}], + #{env => #{dispatch => Dispatch}}), + ok = hackney_fault_transport:clear(), + ok = hackney_crash_sentinel:start(), + %% Deliberately smaller than the worker count: most rounds dial a fresh + %% overflow connection, which is where connect faults land. + ok = hackney_pool:start_pool(?POOL, [{pool_size, 2}, {prewarm_count, 0}]), + ok. + +teardown(_) -> + ok = hackney_fault_transport:clear(), + _ = hackney_crash_sentinel:stop(), + _ = (try hackney_pool:stop_pool(?POOL) catch _:_ -> ok end), + _ = (try cowboy:stop_listener(chaos_test_server) catch _:_ -> ok end), + application:stop(cowboy), + application:stop(hackney), + error_logger:tty(true), + ok. + +%%==================================================================== +%% The run +%%==================================================================== + +t_chaos() -> + Pool = hackney_pool:find_pool(?POOL), + %% Other suites in the same VM leave connections running: "nothing leaked" + %% is judged against what was already there. + Baseline = conn_count(), + Workers = env(<<"HACKNEY_CHAOS_WORKERS">>, 12), + Rounds = env(<<"HACKNEY_CHAOS_ROUNDS">>, 400), + Seed = env(<<"HACKNEY_CHAOS_SEED">>, 42), + ?debugFmt("chaos: ~b workers x ~b rounds, seed ~b", [Workers, Rounds, Seed]), + + Monkey = spawn_link(fun() -> monkey() end), + Parent = self(), + Pids = [spawn_link(fun() -> worker(Parent, Seed + N, Rounds) end) + || N <- lists:seq(1, Workers)], + Tally = await(Pids, #{}, deadline(120000)), + Monkey ! stop, + ok = hackney_fault_transport:clear(), + ?debugFmt("chaos: ~b dials, ~b sends, outcomes ~p", + [hackney_fault_transport:calls(connect), + hackney_fault_transport:calls(send), + maps:to_list(Tally)]), + + %% The pool never died and nothing is left behind. + ?assertEqual(Pool, hackney_pool:find_pool(?POOL)), + ?assert(is_process_alive(Pool)), + hackney_crash_sentinel:assert_no_crash_from(Pool), + Stats = wait_until(fun() -> + S = hackney_pool:get_stats(?POOL), + settled(S, Baseline) andalso S + end, 10000), + ?assertEqual(0, proplists:get_value(in_use_count, Stats)), + ?assertEqual(0, proplists:get_value(queue_count, Stats)), + + %% The run actually exercised both sides: requests got through between + %% fault windows, and dials failed while faults were armed. Without these + %% the suite would still pass if every checkout started failing, or if the + %% faults stopped reaching the code under test. + ?assert(maps:get({status, 200}, Tally, 0) > 0), + ?assert(checkout_errors(Tally) > 0), + + %% And it still works. A pool that survives by wedging is no better than a + %% pool that died. + [?assertEqual(ok, one_request()) || _ <- lists:seq(1, 10)], + ok. + +%%==================================================================== +%% Workers +%%==================================================================== + +%% One round: take a connection, maybe use it, then give it back the polite +%% way, the rude way, or not at all. +worker(Parent, Seed, Rounds) -> + rand:seed(exsss, {Seed, Seed * 7, Seed * 13}), + Tally = lists:foldl(fun(_, Acc) -> count(round_trip(), Acc) end, + #{}, lists:seq(1, Rounds)), + Parent ! {done, self(), Tally}. + +round_trip() -> + Opts = [{pool, ?POOL}, {connect_timeout, 200}, {checkout_timeout, 5000}], + case hackney_pool:checkout(?HOST, ?PORT, hackney_fault_transport, Opts) of + {ok, PoolInfo, Pid} -> + Outcome = use(Pid), + release(PoolInfo, Pid), + Outcome; + {error, Reason} -> + {checkout_error, Reason} + end. + +use(Pid) -> + case rand:uniform(10) of + 1 -> + %% Checked out and abandoned without a request. + idle; + _ -> + try hackney_conn:request(Pid, <<"GET">>, <<"/get">>, [], <<>>) of + {ok, Status, _Headers} -> {status, Status}; + {ok, Status, _Headers, _Body} -> {status, Status}; + {error, Reason} -> {request_error, Reason} + catch + _:_ -> request_exit + end + end. + +release(PoolInfo, Pid) -> + case rand:uniform(10) of + 1 -> + %% The connection dies with the caller holding it. + exit(Pid, kill); + 2 -> + %% The caller never checks in: the pool learns through its monitor. + ok; + _ -> + _ = (try hackney_pool:checkin(PoolInfo, Pid) catch _:_ -> ok end), + ok + end. + +%%==================================================================== +%% Chaos monkey +%%==================================================================== + +%% Arms one fault at a time, holds it briefly, clears it, moves to the next. +%% It rotates through the whole matrix instead of picking at random: with a +%% fixed seed a random monkey reproducibly skips whole callbacks, and a run +%% that never arms a connect fault never tests the path issue #927 lived on. +%% The chaos comes from where the faults land relative to concurrent callers, +%% not from the order they are armed in. +monkey() -> + monkey_loop(matrix()). + +matrix() -> + [{Callback, Fault} + || Callback <- [connect, send, recv, close, setopts], + Fault <- [{slow_error, 50}, {sleep, 30}, crash, + {error, econnrefused}, {error, closed}, {hang, 300}]]. + +monkey_loop([]) -> + monkey_loop(matrix()); +monkey_loop([{Callback, Fault} | Rest]) -> + hackney_fault_transport:set(Callback, Fault), + receive stop -> ok + after 15 -> + hackney_fault_transport:clear(Callback), + %% The quiet gaps are half the test: they are when the pool has to + %% recover and serve normally again. + receive stop -> ok + after 25 -> monkey_loop(Rest) + end + end. + +%%==================================================================== +%% Helpers +%%==================================================================== + +one_request() -> + Opts = [{pool, ?POOL}, {connect_timeout, 5000}, {checkout_timeout, 5000}], + case hackney_pool:checkout(?HOST, ?PORT, hackney_fault_transport, Opts) of + {ok, PoolInfo, Pid} -> + Result = hackney_conn:request(Pid, <<"GET">>, <<"/get">>, [], <<>>), + ok = hackney_pool:checkin(PoolInfo, Pid), + case Result of + {ok, 200, _} -> ok; + {ok, 200, _, _} -> ok; + Other -> {unexpected, Other} + end; + Error -> + {checkout_failed, Error} + end. + +await([], Tally, _Deadline) -> + Tally; +await(Pids, Tally, Deadline) -> + Left = Deadline - erlang:monotonic_time(millisecond), + ?assert(Left > 0), + receive + {done, Pid, WorkerTally} -> + await(Pids -- [Pid], merge(Tally, WorkerTally), Deadline) + after Left -> + erlang:error({chaos_workers_stuck, length(Pids)}) + end. + +settled(Stats, Baseline) -> + proplists:get_value(in_use_count, Stats) =:= 0 andalso + proplists:get_value(queue_count, Stats) =:= 0 andalso + conn_count() =< Baseline + proplists:get_value(free_count, Stats). + +conn_count() -> + case whereis(hackney_conn_sup) of + undefined -> 0; + _ -> proplists:get_value(active, supervisor:count_children(hackney_conn_sup)) + end. + +checkout_errors(Tally) -> + maps:fold(fun({checkout_error, _}, N, Acc) -> Acc + N; + (_, _, Acc) -> Acc + end, 0, Tally). + +count(Outcome, Tally) -> + Key = case Outcome of + {status, Status} -> {status, Status}; + {checkout_error, Reason} -> {checkout_error, class(Reason)}; + {request_error, Reason} -> {request_error, class(Reason)}; + Other -> Other + end, + maps:update_with(Key, fun(N) -> N + 1 end, 1, Tally). + +%% Keep the tally readable: crash reasons carry stacktraces. +class(Reason) when is_atom(Reason) -> Reason; +class({Reason, _}) when is_atom(Reason) -> Reason; +class(_) -> other. + +merge(A, B) -> + maps:fold(fun(K, V, Acc) -> maps:update_with(K, fun(N) -> N + V end, V, Acc) end, + A, B). + +deadline(Ms) -> erlang:monotonic_time(millisecond) + Ms. + +env(Name, Default) -> + case os:getenv(binary_to_list(Name)) of + false -> Default; + Value -> list_to_integer(Value) + end. + +wait_until(Fun, Timeout) -> + poll(Fun, deadline(Timeout)). + +poll(Fun, Deadline) -> + case Fun() of + false -> + ?assert(erlang:monotonic_time(millisecond) < Deadline), + timer:sleep(50), + poll(Fun, Deadline); + Value -> + Value + end. diff --git a/test/hackney_pool_fault_tests.erl b/test/hackney_pool_fault_tests.erl new file mode 100644 index 00000000..b1d4f1bd --- /dev/null +++ b/test/hackney_pool_fault_tests.erl @@ -0,0 +1,290 @@ +%%% -*- erlang -*- +%%% +%%% This file is part of hackney released under the Apache 2 license. +%%% See the NOTICE for more information. +%%% +%%% @doc Fault injection around the pool: every way a connection attempt can +%%% go wrong must come back as a checkout error, never as a dead pool. +%%% +%%% The pool dials connections from inside its own gen_server, so any call into +%%% a connection process that raises takes the pool down with it and every +%%% caller of that pool with it (issue #927). Ordinary integration tests never +%%% see this: they only exercise servers that answer. Each scenario here arms +%%% one fault through {@link hackney_fault_transport}, drives one checkout +%%% entry point, and asserts the same four invariants: +%%% +%%%
    +%%%
  1. the caller gets `{error, _}', not an exit
    2. +%%%
  2. the pool process is the same pid it was before (it never died and +%%% got restarted under the same name)
    3. +%%%
  3. nothing is left checked out or queued
    4. +%%%
  4. no connection process leaked, and no crash report was logged
    5. +%%%
+-module(hackney_pool_fault_tests). + +-include_lib("eunit/include/eunit.hrl"). + +-define(POOL, fault_test_pool). +-define(HOST, "127.0.0.1"). +-define(PORT, 8141). + +%%==================================================================== +%% Fixtures +%%==================================================================== + +pool_fault_test_() -> + {setup, + fun start_server/0, + fun stop_server/1, + {foreach, + fun setup/0, + fun teardown/1, + [ + scenario("a connect that outlives its timeout is a checkout error (#927)", + fun t_connect_outlives_timeout/1), + scenario("a connect that never answers is a checkout error", + fun t_connect_hangs/1), + scenario("a connection crashing while dialing is a checkout error", + fun t_connect_crashes/1), + scenario("a refused connect is a checkout error", + fun t_connect_refused/1), + scenario("checkout_ssl turns a failed dial into a checkout error", + fun t_checkout_ssl_dial_failure/1), + scenario("a failed checkout leaves the next one working", + fun t_pool_still_serves_after_fault/1), + scenario("a connection crashing mid-request does not crash the pool", + fun t_crash_mid_request/1), + scenario("a connection killed while checked out does not crash the pool", + fun t_kill_checked_out_connection/1), + scenario("a fault storm never takes the pool down", 60, + fun t_fault_storm/1) + ]}}. + +%% Each scenario runs against the connection count it started with: other +%% suites in the same VM leave connections running, so "no connection leaked" +%% can only be judged relative to a baseline. +scenario(Description, Test) -> + fun(Baseline) -> {Description, fun() -> Test(Baseline) end} end. + +scenario(Description, Timeout, Test) -> + fun(Baseline) -> + {Description, {timeout, Timeout, fun() -> Test(Baseline) end}} + end. + +%% The listener lives for the whole module: rebinding the same port between +%% scenarios races with the previous listener shutting down. +start_server() -> + error_logger:tty(false), + {ok, _} = application:ensure_all_started(cowboy), + {ok, _} = application:ensure_all_started(hackney), + Dispatch = cowboy_router:compile([{'_', [{"/[...]", test_http_resource, []}]}]), + {ok, _} = cowboy:start_clear(fault_test_server, [{port, ?PORT}], + #{env => #{dispatch => Dispatch}}), + ok. + +stop_server(_) -> + _ = (try cowboy:stop_listener(fault_test_server) catch _:_ -> ok end), + application:stop(cowboy), + application:stop(hackney), + error_logger:tty(true), + ok. + +setup() -> + ok = hackney_fault_transport:clear(), + ok = hackney_crash_sentinel:start(), + ok = hackney_pool:start_pool(?POOL, [{pool_size, 4}, {prewarm_count, 0}]), + conn_count(). + +teardown(_) -> + ok = hackney_fault_transport:clear(), + _ = hackney_crash_sentinel:stop(), + _ = (try hackney_pool:stop_pool(?POOL) catch _:_ -> ok end), + ok. + +%%==================================================================== +%% Connect-time faults +%%==================================================================== + +%% The reported regression: the transport is still dialling when the deadline +%% passes. Before the fix the pool exited with `{timeout, {gen_statem, call, _}}'. +t_connect_outlives_timeout(Baseline) -> + hackney_fault_transport:set(connect, {slow_error, 300}), + ?assertEqual({error, connect_timeout}, checkout([{connect_timeout, 30}])), + assert_pool_healthy(Baseline). + +%% Same shape, except the transport never answers at all. The pool must not be +%% held hostage by it either: the checkout has to come back on its own deadline. +t_connect_hangs(Baseline) -> + hackney_fault_transport:set(connect, {hang, 1500}), + {Elapsed, Result} = timer:tc(fun() -> checkout([{connect_timeout, 50}]) end), + ?assertEqual({error, connect_timeout}, Result), + %% Back well before the transport finishes hanging: the checkout deadline + %% plus the bounded stop, not the 1.5s the transport sits there for. + ?assert(Elapsed div 1000 < 800), + assert_pool_healthy(Baseline). + +t_connect_crashes(Baseline) -> + hackney_fault_transport:set(connect, crash), + ?assertMatch({error, {{simulated_crash, connect}, _}}, + checkout([{connect_timeout, 1000}])), + assert_pool_healthy(Baseline). + +t_connect_refused(Baseline) -> + hackney_fault_transport:set(connect, {error, econnrefused}), + ?assertEqual({error, econnrefused}, checkout([{connect_timeout, 1000}])), + assert_pool_healthy(Baseline). + +%% checkout_ssl reaches start_connection through its own path +%% (checkout_ssl_fallback), which always dials hackney_tcp, so the fault +%% transport cannot be injected there. Point it at a closed port instead: what +%% matters is that the entry point turns a failed dial into a checkout error. +t_checkout_ssl_dial_failure(Baseline) -> + Opts = [{pool, ?POOL}, {connect_timeout, 500}, {checkout_timeout, 2000}], + ?assertMatch({error, _}, + hackney_pool:checkout_ssl(?HOST, closed_port(), hackney_ssl, Opts)), + assert_pool_healthy(Baseline). + +%% A pool that survives a fault is only useful if it still serves: the failed +%% attempt must not have leaked a slot, a monitor, or a queued caller. +t_pool_still_serves_after_fault(Baseline) -> + hackney_fault_transport:set(connect, crash), + ?assertMatch({error, _}, checkout([{connect_timeout, 1000}])), + ok = hackney_fault_transport:clear(), + {ok, PoolInfo, Pid} = checkout_ok(), + ?assert(is_process_alive(Pid)), + ok = hackney_pool:checkin(PoolInfo, Pid), + assert_pool_healthy(Baseline). + +%%==================================================================== +%% Faults on a checked out connection +%%==================================================================== + +%% The connection dies with the caller holding it. The pool learns about it +%% through its monitor, and must drain the checkout rather than crash. +t_crash_mid_request(Baseline) -> + {ok, _PoolInfo, Pid} = checkout_ok(), + hackney_fault_transport:set(send, crash), + %% The caller sees the failure either way; what matters is the pool. + try hackney_conn:request(Pid, <<"GET">>, <<"/get">>, [], <<>>) of + {error, _} -> ok; + Other -> erlang:error({unexpected_request_result, Other}) + catch + _:_ -> ok + end, + assert_pool_healthy(Baseline). + +t_kill_checked_out_connection(Baseline) -> + {ok, _PoolInfo, Pid} = checkout_ok(), + exit(Pid, kill), + assert_pool_healthy(Baseline). + +%%==================================================================== +%% Storm +%%==================================================================== + +%% Every fault, from many callers at once, against a pool small enough that +%% they contend for it. Nothing here should reach the pool as an exit. +t_fault_storm(Baseline) -> + Faults = [{slow_error, 50}, crash, {error, econnrefused}, {sleep, 20}, ok], + Parent = self(), + Workers = [spawn_link(fun() -> storm_worker(Parent, N, Faults) end) + || N <- lists:seq(1, 20)], + %% One deadline for the whole storm, not one per worker: a pool held + %% hostage by a slow connection shows up here as workers that never finish. + await_workers(Workers, erlang:monotonic_time(millisecond) + 30000), + ok = hackney_fault_transport:clear(), + assert_pool_healthy(Baseline). + +await_workers([], _Deadline) -> + ok; +await_workers(Workers, Deadline) -> + Left = Deadline - erlang:monotonic_time(millisecond), + ?assert(Left > 0), + receive + {done, W} -> await_workers(Workers -- [W], Deadline) + after Left -> + erlang:error({storm_workers_stuck, length(Workers)}) + end. + +storm_worker(Parent, Seed, Faults) -> + rand:seed(exsss, {Seed, Seed * 7, Seed * 13}), + lists:foreach( + fun(_) -> + Fault = lists:nth(rand:uniform(length(Faults)), Faults), + hackney_fault_transport:set(connect, Fault), + case checkout([{connect_timeout, 100}, {checkout_timeout, 5000}]) of + {ok, PoolInfo, Pid} -> + _ = (try hackney_pool:checkin(PoolInfo, Pid) catch _:_ -> ok end); + {error, _} -> + ok + end + end, + lists:seq(1, 10)), + Parent ! {done, self()}. + +%%==================================================================== +%% Helpers +%%==================================================================== + +checkout(Extra) -> + Opts = [{pool, ?POOL}, {checkout_timeout, 2000} | Extra], + hackney_pool:checkout(?HOST, ?PORT, hackney_fault_transport, Opts). + +checkout_ok() -> + ok = hackney_fault_transport:clear(), + case checkout([{connect_timeout, 2000}]) of + {ok, _, _} = Ok -> Ok; + Other -> erlang:error({checkout_failed, Other}) + end. + +%% The four invariants every scenario shares. +assert_pool_healthy(Baseline) -> + Pool = hackney_pool:find_pool(?POOL), + ?assert(is_pid(Pool) andalso is_process_alive(Pool)), + hackney_crash_sentinel:assert_no_crash_from(Pool), + Stats = wait_until(fun() -> + S = hackney_pool:get_stats(?POOL), + settled(S, Baseline) andalso S + end, 5000), + ?assertEqual(0, proplists:get_value(in_use_count, Stats)), + ?assertEqual(0, proplists:get_value(queue_count, Stats)), + ok. + +%% Nothing checked out, nobody queued, and no connection process alive beyond +%% the ones the pool is keeping warm: a failed attempt that leaves a connection +%% behind is a leak even when the pool itself survived. +settled(Stats, Baseline) -> + proplists:get_value(in_use_count, Stats) =:= 0 andalso + proplists:get_value(queue_count, Stats) =:= 0 andalso + conn_count() =< Baseline + proplists:get_value(free_count, Stats). + +%% A port nothing listens on: bind one, note it, hand it back. +closed_port() -> + {ok, L} = gen_tcp:listen(0, [{active, false}]), + {ok, Port} = inet:port(L), + ok = gen_tcp:close(L), + Port. + +conn_count() -> + case whereis(hackney_conn_sup) of + undefined -> 0; + _ -> proplists:get_value(active, supervisor:count_children(hackney_conn_sup)) + end. + +%% Poll `Fun' until it returns something other than `false'. +wait_until(Fun, Timeout) -> + wait_until(Fun, Timeout, erlang:monotonic_time(millisecond)). + +wait_until(Fun, Timeout, Start) -> + case Fun() of + false -> + Now = erlang:monotonic_time(millisecond), + case Now - Start > Timeout of + true -> erlang:error({timeout_waiting_for, Fun}); + false -> + timer:sleep(20), + wait_until(Fun, Timeout, Start) + end; + Value -> + Value + end. diff --git a/test/hackney_pool_h2h3_fault_tests.erl b/test/hackney_pool_h2h3_fault_tests.erl new file mode 100644 index 00000000..db7b895b --- /dev/null +++ b/test/hackney_pool_h2h3_fault_tests.erl @@ -0,0 +1,175 @@ +%%% -*- erlang -*- +%%% +%%% This file is part of hackney released under the Apache 2 license. +%%% See the NOTICE for more information. +%%% +%%% @doc Fault injection on the multiplexed checkout paths. +%%% +%%% HTTP/2 and HTTP/3 connections are not checked out exclusively: the pool +%%% keeps one per host and hands the same pid to every caller. That makes a +%%% single bad connection worse than on the HTTP/1 path, because every request +%%% to that host goes through the same probe. The pool must answer `none' for a +%%% connection that is dead, wedged, or dies while being probed, and it must +%%% answer quickly: a probe that blocks holds every caller of the pool, not +%%% just the one that asked. +-module(hackney_pool_h2h3_fault_tests). + +-include_lib("eunit/include/eunit.hrl"). + +-define(POOL, h2h3_fault_test_pool). +-define(HOST, "127.0.0.1"). +-define(PORT, 8143). + +%% A probe of a wedged connection has to come back in well under the time it +%% would take if it waited for the connection itself. +-define(PROBE_BUDGET_MS, 1000). + +%%==================================================================== +%% Fixtures +%%==================================================================== + +h2h3_fault_test_() -> + {setup, + fun start_server/0, + fun stop_server/1, + {foreach, + fun setup/0, + fun teardown/1, + [ + {"a healthy h2 connection is handed out", fun t_h2_healthy/0}, + {"a wedged h2 connection is dropped without stalling the pool", + fun t_h2_wedged/0}, + {"an h2 connection that dies when probed does not crash the pool", + fun t_h2_dies_when_probed/0}, + {"a dead h2 connection is dropped", fun t_h2_dead/0}, + {"a dead h3 connection is dropped", fun t_h3_dead/0}, + {"a wedged h3 connection does not stall the pool", fun t_h3_wedged/0} + ]}}. + +%% The listener lives for the whole module: rebinding the same port between +%% scenarios races with the previous listener shutting down. +start_server() -> + error_logger:tty(false), + {ok, _} = application:ensure_all_started(cowboy), + {ok, _} = application:ensure_all_started(hackney), + Dispatch = cowboy_router:compile([{'_', [{"/[...]", test_http_resource, []}]}]), + {ok, _} = cowboy:start_clear(h2h3_fault_test_server, [{port, ?PORT}], + #{env => #{dispatch => Dispatch}}), + ok. + +stop_server(_) -> + _ = (try cowboy:stop_listener(h2h3_fault_test_server) catch _:_ -> ok end), + application:stop(cowboy), + application:stop(hackney), + error_logger:tty(true), + ok. + +setup() -> + ok = hackney_crash_sentinel:start(), + ok = hackney_pool:start_pool(?POOL, [{pool_size, 4}, {prewarm_count, 0}]), + ok. + +teardown(_) -> + _ = hackney_crash_sentinel:stop(), + _ = (try hackney_pool:stop_pool(?POOL) catch _:_ -> ok end), + ok. + +%%==================================================================== +%% HTTP/2 +%%==================================================================== + +t_h2_healthy() -> + Pid = live_conn(), + ok = hackney_pool:register_h2(?HOST, ?PORT, hackney_tcp, Pid, opts()), + ?assertEqual({ok, Pid}, checkout_h2()), + assert_pool_healthy(). + +%% The connection is alive but answers nothing. Before `get_state' took a +%% timeout the pool sat on the default 5s call for every caller of that host. +t_h2_wedged() -> + Pid = live_conn(), + ok = hackney_pool:register_h2(?HOST, ?PORT, hackney_tcp, Pid, opts()), + ok = sys:suspend(Pid), + {Elapsed, Result} = timer:tc(fun checkout_h2/0), + exit(Pid, kill), + ?assertEqual(none, Result), + ?assert(Elapsed div 1000 < ?PROBE_BUDGET_MS), + assert_pool_healthy(). + +%% Alive when registered, gone by the time the pool asks it anything. +t_h2_dies_when_probed() -> + Pid = spawn(fun() -> receive _ -> exit(probed) end end), + ok = hackney_pool:register_h2(?HOST, ?PORT, hackney_tcp, Pid, opts()), + ?assertEqual(none, checkout_h2()), + assert_pool_healthy(). + +t_h2_dead() -> + Pid = live_conn(), + ok = hackney_pool:register_h2(?HOST, ?PORT, hackney_tcp, Pid, opts()), + ?assertEqual({ok, Pid}, checkout_h2()), + exit(Pid, kill), + ?assertEqual(none, checkout_h2()), + ?assertEqual(none, checkout_h2()), + assert_pool_healthy(). + +%%==================================================================== +%% HTTP/3 +%%==================================================================== + +t_h3_dead() -> + Pid = live_conn(), + ok = hackney_pool:register_h3(?HOST, ?PORT, hackney_tcp, Pid, opts()), + ?assertEqual({ok, Pid}, checkout_h3()), + exit(Pid, kill), + ?assertEqual(none, checkout_h3()), + assert_pool_healthy(). + +t_h3_wedged() -> + Pid = live_conn(), + ok = hackney_pool:register_h3(?HOST, ?PORT, hackney_tcp, Pid, opts()), + ok = sys:suspend(Pid), + {Elapsed, _Result} = timer:tc(fun checkout_h3/0), + exit(Pid, kill), + ?assert(Elapsed div 1000 < ?PROBE_BUDGET_MS), + assert_pool_healthy(). + +%%==================================================================== +%% Helpers +%%==================================================================== + +opts() -> [{pool, ?POOL}]. + +checkout_h2() -> + hackney_pool:checkout_h2(?HOST, ?PORT, hackney_tcp, opts()). + +checkout_h3() -> + hackney_pool:checkout_h3(?HOST, ?PORT, hackney_tcp, opts()). + +%% A real connection process against the test server, outside the pool's +%% checkout bookkeeping: these tests are about the shared-connection map. +live_conn() -> + {ok, Pid} = hackney_conn_sup:start_conn(#{ + host => ?HOST, + port => ?PORT, + transport => hackney_tcp, + connect_timeout => 5000, + recv_timeout => 5000, + idle_timeout => infinity, + ssl_options => [], + connect_options => [], + pool_pid => self(), + owner => self() + }), + ok = hackney_conn:connect(Pid), + Pid. + +assert_pool_healthy() -> + Pool = hackney_pool:find_pool(?POOL), + ?assert(is_pid(Pool) andalso is_process_alive(Pool)), + hackney_crash_sentinel:assert_no_crash_from(Pool), + %% Still answering, and promptly: the probe failures above must not have + %% left the pool blocked on anything. + {Elapsed, Stats} = timer:tc(fun() -> hackney_pool:get_stats(?POOL) end), + ?assert(Elapsed div 1000 < ?PROBE_BUDGET_MS), + ?assertEqual(0, proplists:get_value(queue_count, Stats)), + ok. diff --git a/test/hackney_pool_safety_tests.erl b/test/hackney_pool_safety_tests.erl new file mode 100644 index 00000000..4c5ef14b --- /dev/null +++ b/test/hackney_pool_safety_tests.erl @@ -0,0 +1,77 @@ +%%% -*- erlang -*- +%%% +%%% This file is part of hackney released under the Apache 2 license. +%%% See the NOTICE for more information. +%%% +%%% @doc Structural test: the pool must never let a connection process take it +%%% down. +%%% +%%% The pool talks to connection processes with synchronous calls made from +%%% inside its own gen_server. Every one of those calls can exit: the conn can +%%% be gone (`noproc'), wedged in a transport call (`timeout'), or crash while +%%% answering. An unguarded call turns any of those into a dead pool and a dead +%%% pool takes every caller with it, which is how issue #927 was reported. +%%% +%%% Rather than wait for each of those to be found in production, this walks +%%% the compiled abstract code of `hackney_pool' and fails on any call into +%%% `hackney_conn' that is not lexically inside a `try'. When it fails, the fix +%%% is to route the call through a guarded helper next to the others in +%%% `hackney_pool' (`connect_connection/2', `stop_conn/1', `checkin_info/1'), +%%% not to relax the check. +-module(hackney_pool_safety_tests). + +-include_lib("eunit/include/eunit.hrl"). + +%% Calls that cannot raise: casts are fire and forget. +-define(SAFE_BY_NATURE, [set_owner_async]). + +conn_calls_are_guarded_test() -> + Unguarded = [Call || Call <- conn_calls(hackney_pool), unguarded(Call)], + ?assertEqual([], Unguarded). + +%% The same rule holds for the connection supervisor: nothing there may raise +%% into a caller either. +conn_sup_calls_are_guarded_test() -> + Unguarded = [Call || Call <- conn_calls(hackney_conn_sup), unguarded(Call)], + ?assertEqual([], Unguarded). + +unguarded({_Where, _Line, Fun, Guarded}) -> + not (Guarded orelse lists:member(Fun, ?SAFE_BY_NATURE)). + +%%==================================================================== +%% Abstract code walk +%%==================================================================== + +%% Returns {Function/Arity, Line, CalledFun, InsideTry} per hackney_conn call. +conn_calls(Module) -> + lists:flatmap( + fun({function, _, Name, Arity, Clauses}) -> + Where = lists:flatten(io_lib:format("~s/~b", [Name, Arity])), + walk(Clauses, Where, false); + (_Other) -> + [] + end, + abstract_code(Module)). + +%% Read the beam through the code server rather than a path: it works the same +%% whether the module is loaded, cover compiled, or only on the code path. +abstract_code(Module) -> + {Module, Beam, _File} = code:get_object_code(Module), + {ok, {Module, [{abstract_code, {raw_abstract_v1, Forms}}]}} = + beam_lib:chunks(Beam, [abstract_code]), + Forms. + +%% A hand walk rather than erl_syntax: all this needs is "is there a try +%% between me and the enclosing function". +walk({'try', _Line, Body, Cases, Catches, After}, Where, _InTry) -> + walk(Body, Where, true) ++ walk(Cases, Where, true) ++ + walk(Catches, Where, true) ++ walk(After, Where, true); +walk({call, Line, {remote, _, {atom, _, hackney_conn}, {atom, _, Fun}}, Args}, + Where, InTry) -> + [{Where, Line, Fun, InTry} | walk(Args, Where, InTry)]; +walk(Tuple, Where, InTry) when is_tuple(Tuple) -> + walk(tuple_to_list(Tuple), Where, InTry); +walk(List, Where, InTry) when is_list(List) -> + lists:flatmap(fun(Item) -> walk(Item, Where, InTry) end, List); +walk(_Other, _Where, _InTry) -> + []. diff --git a/test/hackney_pool_tests.erl b/test/hackney_pool_tests.erl index 0b0ac6cf..c999f370 100644 --- a/test/hackney_pool_tests.erl +++ b/test/hackney_pool_tests.erl @@ -9,6 +9,8 @@ -module(hackney_pool_tests). +-export([connect/4]). + -include_lib("eunit/include/eunit.hrl"). -include("hackney.hrl"). @@ -56,6 +58,10 @@ hackney_pool_integration_test_() -> {"owner crash kills connection", fun test_owner_crash/0}, {"checkin resets owner to pool", fun test_checkin_resets_owner/0}, {"prewarm creates connections", fun test_prewarm/0}, + {"connect timeout does not crash the pool", + fun test_connect_timeout_does_not_crash_pool/0}, + {"connect crash does not crash the pool", + fun test_connect_crash_does_not_crash_pool/0}, {"queue timeout", {timeout, 120, fun test_queue_timeout/0}}, {"checkout timeout", {timeout, 120, fun test_checkout_timeout/0}}, {"stop_pool releases in_use load_regulation slots", @@ -130,6 +136,14 @@ teardown_integration(_) -> error_logger:tty(true), ok. +%% Stub transport: "slow.example" outlives the connect timeout, "crash.example" +%% takes the connection process down while dialing. +connect("slow.example", _Port, _Opts, _Timeout) -> + timer:sleep(100), + {error, simulated_timeout}; +connect("crash.example", _Port, _Opts, _Timeout) -> + erlang:error(simulated_crash). + setup_ssl() -> error_logger:tty(false), {ok, _} = application:ensure_all_started(cowboy), @@ -742,6 +756,24 @@ test_prewarm() -> ok = hackney_pool:stop_pool(test_pool_prewarm). +test_connect_timeout_does_not_crash_pool() -> + PoolName = test_pool_connect_timeout, + ok = hackney_pool:start_pool(PoolName, [{pool_size, 1}, {prewarm_count, 0}]), + Opts = [{pool, PoolName}, {connect_timeout, 10}, {checkout_timeout, 1000}], + ?assertEqual({error, connect_timeout}, + hackney_pool:checkout("slow.example", 443, ?MODULE, Opts)), + ?assert(is_process_alive(hackney_pool:find_pool(PoolName))), + ok = hackney_pool:stop_pool(PoolName). + +test_connect_crash_does_not_crash_pool() -> + PoolName = test_pool_connect_crash, + ok = hackney_pool:start_pool(PoolName, [{pool_size, 1}, {prewarm_count, 0}]), + Opts = [{pool, PoolName}, {connect_timeout, 1000}, {checkout_timeout, 2000}], + ?assertMatch({error, {simulated_crash, _}}, + hackney_pool:checkout("crash.example", 443, ?MODULE, Opts)), + ?assert(is_process_alive(hackney_pool:find_pool(PoolName))), + ok = hackney_pool:stop_pool(PoolName). + %%==================================================================== %% Timeout Tests %%====================================================================