Improve test timeout handling in gun_SUITE

Instead of timeouts, favor receiving events from the event
handler gun_test_event_h. Remove most other timeouts in particular
receive timeouts in favor of a Common Test timetrap timeout global
to this test suite of 30 seconds.

2 files changed, 215 insertions, 138 deletions

diff --git a/test/gun_SUITE.erl b/test/gun_SUITE.erl
index 0667cac..ca8dab5 100644
--- a/test/gun_SUITE.erl
+++ b/test/gun_SUITE.erl
@@ -22,18 +22,17 @@
 -import(gun_test, [init_origin/3]).
 -import(gun_test, [receive_from/1]).
 -import(gun_test, [receive_all_from/2]).
+-import(gun_test_event_h, [receive_event/1]).
+-import(gun_test_event_h, [receive_event/2]).
+
+suite() ->
+	[{timetrap, 30000}].
 
 all() ->
 	[{group, gun}].
 
 groups() ->
-	%% On Windows we sometimes have timeout related failures due to
-	%% some operations taking longer. Best retry a few times.
-	Props = case os:type() of
-		{win32, _} -> [{repeat_until_all_ok, 10}];
-		_ -> []
-	end,
-	[{gun, [parallel|Props], ct_helper:all(?MODULE)}].
+	[{gun, [parallel], ct_helper:all(?MODULE)}].
 
 %% Tests.
 
@@ -80,17 +79,17 @@ domain_lookup_timeout_infinity(_) ->
 	do_timeout(domain_lookup_timeout, infinity).
 
 do_timeout(Opt, Timeout) ->
-	{ok, Pid} = gun:open("localhost", 12345, #{Opt => Timeout, retry => 0}),
-	Ref = monitor(process, Pid),
-	receive
-		{'DOWN', Ref, process, Pid, {shutdown, _}} ->
-			ok
-	after 2000 ->
-		%% This is not an error, the timeout was accepted but
-		%% the connect or domain lookup is just taking too long,
-		%% for example when it was set to infinity.
-		gun:close(Pid)
-	end.
+	{ok, ConnPid} = gun:open("localhost", 12345, #{
+		Opt => Timeout,
+		event_handler => {gun_test_event_h, self()},
+		retry => 0
+	}),
+	%% The connection will not succeed. We will however receive
+	%% an init event from the connection process that indicates
+	%% that the timeout value was accepted, since the timeout
+	%% checks occur earlier.
+	{_, init, _} = receive_event(ConnPid),
+	gun:close(ConnPid).
 
 ignore_empty_data_http(_) ->
 	doc("When gun:data/4 is called with nofin and empty data, it must be ignored."),
@@ -140,17 +139,18 @@ info(_) ->
 
 keepalive_infinity(_) ->
 	doc("Ensure infinity for keepalive is accepted by all protocols."),
-	{ok, Pid} = gun:open("localhost", 12345, #{
+	{ok, ConnPid} = gun:open("localhost", 12345, #{
+		event_handler => {gun_test_event_h, self()},
 		http_opts => #{keepalive => infinity},
 		http2_opts => #{keepalive => infinity},
-		retry => 0}),
-	Ref = monitor(process, Pid),
-	receive
-		{'DOWN', Ref, process, Pid, {shutdown, _}} ->
-			ok
-	after 5000 ->
-		error(timeout)
-	end.
+		retry => 0
+	}),
+	%% The connection will not succeed. We will however receive
+	%% an init event from the connection process that indicates
+	%% that the timeout value was accepted, since the timeout
+	%% checks occur earlier.
+	{_, init, _} = receive_event(ConnPid),
+	gun:close(ConnPid).
 
 killed_streams_http(_) ->
 	doc("Ensure completed responses with a connection: close are not considered killed streams."),
@@ -174,8 +174,6 @@ killed_streams_http(_) ->
 		{gun_down, ConnPid, http, normal, KilledStreams} ->
 			[] = KilledStreams,
 			gun:close(ConnPid)
-	after 1000 ->
-		error(timeout)
 	end.
 
 list_header_name(_) ->
@@ -209,22 +207,22 @@ map_headers(_) ->
 postpone_request_while_not_connected(_) ->
 	doc("Ensure Gun doesn't raise error when requesting in retries"),
 	%% Try connecting to a server that isn't up yet.
-	{ok, Pid} = gun:open("localhost", 23456, #{retry => 5, retry_timeout => 1000}),
-	_ = gun:get(Pid, "/postponed"),
-	%% Make sure the connect call completed and we are waiting for a retry.
-	Timeout = case os:type() of
-		{win32, _} -> 2500;
-		_ -> 500
-	end,
-	timer:sleep(Timeout),
+	{ok, ConnPid} = gun:open("localhost", 23456, #{
+		event_handler => {gun_test_event_h, self()},
+		retry => 5,
+		retry_timeout => 1000
+	}),
+	_ = gun:get(ConnPid, "/postponed"),
+	%% Wait for the connection attempt. to fail.
+	{_, connect_end, #{error := _}} = receive_event(ConnPid, connect_end),
 	%% Start the server so that next retry will result in the client connecting successfully.
 	{ok, ListenSocket} = gen_tcp:listen(23456, [binary, {active, false}, {reuseaddr, true}]),
 	{ok, ClientSocket} = gen_tcp:accept(ListenSocket, 5000),
 	%% The client should now be up.
-	{ok, http} = gun:await_up(Pid),
+	{ok, http} = gun:await_up(ConnPid),
 	%% The server receives the postponed request.
 	{ok, <<"GET /postponed HTTP/1.1\r\n", _/bits>>} = gen_tcp:recv(ClientSocket, 0, 5000),
-	ok.
+	gun:close(ConnPid).
 
 reply_to(_) ->
 	doc("The reply_to option allows using a separate process for requests."),
@@ -251,8 +249,6 @@ do_reply_to(Protocol) ->
 		receive Ref ->
 			Response = gun:await(Pid, Ref),
 			Self ! Response
-		after 1000 ->
-			error(timeout)
 		end
 	end),
 	Ref = gun:get(Pid, "/", [], #{reply_to => ReplyTo}),
@@ -287,146 +283,164 @@ do_reply_to(Protocol) ->
 	receive
 		{response, _, _, _} ->
 			gun:close(Pid)
-	after 1000 ->
-		error(timeout)
 	end.
 
 retry_0(_) ->
 	doc("Ensure Gun gives up immediately with retry=0."),
-	{ok, Pid} = gun:open("localhost", 12345, #{retry => 0, retry_timeout => 500}),
-	Ref = monitor(process, Pid),
-	%% On Windows when the connection is refused the OS will retry
-	%% a few times before giving up, with a delay between tries.
-	%% This adds time to connection failures.
-	After = case os:type() of
-		{win32, _} -> 2300;
-		_ -> 300
-	end,
-	receive
-		{'DOWN', Ref, process, Pid, {shutdown, _}} ->
-			ok
-	after After ->
-		error(timeout)
-	end.
+	{ok, ConnPid} = gun:open("localhost", 12345, #{
+		event_handler => {gun_test_event_h, self()},
+		retry => 0,
+		retry_timeout => 500
+	}),
+	{_, init, _} = receive_event(ConnPid),
+	{_, domain_lookup_start, _} = receive_event(ConnPid),
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
+	{_, connect_end, #{error := _}} = receive_event(ConnPid),
+	{_, terminate, _} = receive_event(ConnPid),
+	ok.
 
 retry_0_disconnect(_) ->
 	doc("Ensure Gun gives up immediately with retry=0 after a successful connection."),
 	{ok, ListenSocket} = gen_tcp:listen(0, [binary, {active, false}]),
 	{ok, {_, Port}} = inet:sockname(ListenSocket),
-	{ok, Pid} = gun:open("localhost", Port, #{retry => 0, retry_timeout => 500}),
-	Ref = monitor(process, Pid),
-	%% On Windows when the connection is refused the OS will retry
-	%% a few times before giving up, with a delay between tries.
-	%% This adds time to connection failures.
-	After = case os:type() of
-		{win32, _} -> 2300;
-		_ -> 300
-	end,
+	{ok, ConnPid} = gun:open("localhost", Port, #{
+		event_handler => {gun_test_event_h, self()},
+		retry => 0,
+		retry_timeout => 500
+	}),
+	{_, init, _} = receive_event(ConnPid),
+	{_, domain_lookup_start, _} = receive_event(ConnPid),
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
 	%% We accept the connection and then close it to trigger a disconnect.
 	{ok, ClientSocket} = gen_tcp:accept(ListenSocket, 5000),
 	gen_tcp:close(ClientSocket),
-	receive
-		{'DOWN', Ref, process, Pid, {shutdown, _}} ->
-			ok
-	after After ->
-		error(timeout)
-	end.
+	%% Connection was successful.
+	{_, connect_end, ConnectEndEvent} = receive_event(ConnPid),
+	false = maps:is_key(error, ConnectEndEvent),
+	%% When the connection is closed we terminate immediately.
+	{_, disconnect, _} = receive_event(ConnPid),
+	{_, terminate, _} = receive_event(ConnPid),
+	ok.
 
 retry_1(_) ->
 	doc("Ensure Gun gives up with retry=1."),
-	{ok, Pid} = gun:open("localhost", 12345, #{retry => 1, retry_timeout => 500}),
-	Ref = monitor(process, Pid),
-	After = case os:type() of
-		{win32, _} -> 4800;
-		_ -> 800
-	end,
-	receive
-		{'DOWN', Ref, process, Pid, {shutdown, _}} ->
-			ok
-	after After ->
-		error(timeout)
-	end.
+	{ok, ConnPid} = gun:open("localhost", 12345, #{
+		event_handler => {gun_test_event_h, self()},
+		retry => 1,
+		retry_timeout => 500
+	}),
+	{_, init, _} = receive_event(ConnPid),
+	%% Initial attempt.
+	{_, domain_lookup_start, _} = receive_event(ConnPid),
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
+	{_, connect_end, #{error := _}} = receive_event(ConnPid),
+	%% Retry.
+	{_, domain_lookup_start, _} = receive_event(ConnPid),
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
+	{_, connect_end, #{error := _}} = receive_event(ConnPid),
+	{_, terminate, _} = receive_event(ConnPid),
+	ok.
 
 retry_1_disconnect(_) ->
-	doc("Ensure Gun gives up with retry=1 after a successful connection."),
+	doc("Ensure Gun doesn't give up with retry=1 after a successful connection "
+		"and attempts to reconnect immediately, ignoring retry_timeout."),
 	{ok, ListenSocket} = gen_tcp:listen(0, [binary, {active, false}]),
 	{ok, {_, Port}} = inet:sockname(ListenSocket),
-	{ok, Pid} = gun:open("localhost", Port, #{retry => 1, retry_timeout => 500}),
+	{ok, ConnPid} = gun:open("localhost", Port, #{
+		event_handler => {gun_test_event_h, self()},
+		retry => 1,
+		retry_timeout => 30000
+	}),
+	{_, init, _} = receive_event(ConnPid),
+	{_, domain_lookup_start, _} = receive_event(ConnPid),
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
 	%% We accept the connection and then close it to trigger a disconnect.
 	{ok, ClientSocket} = gen_tcp:accept(ListenSocket, 5000),
 	gen_tcp:close(ClientSocket),
-	%% We confirm that Gun reconnects immediately.
-	{ok, _} = gen_tcp:accept(ListenSocket, 200),
-	gun:close(Pid).
+	%% Connection was successful.
+	{_, connect_end, ConnectEndEvent} = receive_event(ConnPid),
+	false = maps:is_key(error, ConnectEndEvent),
+	%% We confirm that Gun reconnects before the retry timeout,
+	%% as it is ignored on the first reconnection.
+	{ok, _} = gen_tcp:accept(ListenSocket, 5000),
+	gun:close(ConnPid).
 
 retry_fun(_) ->
 	doc("Ensure the retry_fun is used when provided."),
-	{ok, Pid} = gun:open("localhost", 12345, #{
+	{ok, ConnPid} = gun:open("localhost", 12345, #{
+		event_handler => {gun_test_event_h, self()},
 		retry => 5,
-		retry_fun => fun(_, _) -> #{retries => 0, timeout => 500} end,
-		retry_timeout => 5000
+		retry_fun => fun(_, _) -> #{retries => 0, timeout => 0} end,
+		retry_timeout => 60000
 	}),
-	Ref = monitor(process, Pid),
-	After = case os:type() of
-		{win32, _} -> 4800;
-		_ -> 800
-	end,
-	receive
-		{'DOWN', Ref, process, Pid, {shutdown, _}} ->
-			ok
-	after After ->
-		error(shutdown_too_late)
-	end.
+	{_, init, _} = receive_event(ConnPid),
+	%% Initial attempt.
+	{_, domain_lookup_start, _} = receive_event(ConnPid),
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
+	{_, connect_end, #{error := _}} = receive_event(ConnPid),
+	%% When retry is not disabled (retry!=0) we necessarily
+	%% have at least one retry attempt using the fun.
+	{_, domain_lookup_start, _} = receive_event(ConnPid),
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
+	{_, connect_end, #{error := _}} = receive_event(ConnPid),
+	{_, terminate, _} = receive_event(ConnPid),
+	ok.
 
 retry_timeout(_) ->
 	doc("Ensure the retry_timeout value is enforced. The first retry is immediate "
 		"and therefore does not use the timeout."),
-	{ok, Pid} = gun:open("localhost", 12345, #{retry => 2, retry_timeout => 1000}),
-	Ref = monitor(process, Pid),
-	After = case os:type() of
-		{win32, _} -> 4800;
-		_ -> 800
-	end,
-	receive
-		{'DOWN', Ref, process, Pid, {shutdown, _}} ->
-			error(shutdown_too_early)
-	after After ->
-		ok
-	end,
-	receive
-		{'DOWN', Ref, process, Pid, {shutdown, _}} ->
-			ok
-	after After ->
-		error(shutdown_too_late)
-	end.
+	{ok, ConnPid} = gun:open("localhost", 12345, #{
+		event_handler => {gun_test_event_h, self()},
+		retry => 2,
+		retry_timeout => 1000
+	}),
+	{_, init, _} = receive_event(ConnPid),
+	%% Initial attempt.
+	{_, domain_lookup_start, _} = receive_event(ConnPid),
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
+	{_, connect_end, #{error := _, ts := TS1}} = receive_event(ConnPid),
+	%% First retry is immediate.
+	{_, domain_lookup_start, #{ts := TS2}} = receive_event(ConnPid),
+	true = (TS2 - TS1) < 1000,
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
+	{_, connect_end, #{error := _, ts := TS3}} = receive_event(ConnPid),
+	%% Second retry occurs after the retry_timeout.
+	{_, domain_lookup_start, #{ts := TS4}} = receive_event(ConnPid),
+	true = (TS4 - TS3) >= 1000,
+	{_, domain_lookup_end, _} = receive_event(ConnPid),
+	{_, connect_start, _} = receive_event(ConnPid),
+	{_, connect_end, #{error := _}} = receive_event(ConnPid),
+	{_, terminate, _} = receive_event(ConnPid),
+	ok.
 
 set_owner(_) ->
 	doc("The owner of the connection can be changed."),
 	Self = self(),
-	Pid = spawn(fun() ->
+	spawn(fun() ->
 		{ok, ConnPid} = gun:open("localhost", 12345),
 		gun:set_owner(ConnPid, Self),
 		Self ! {conn, ConnPid}
 	end),
-	Ref = monitor(process, Pid),
-	receive {'DOWN', Ref, process, Pid, _} -> ok after 1000 -> error(timeout) end,
-	ConnPid = receive {conn, C} -> C after 1000 -> error(timeout) end,
+	ConnPid = receive {conn, C} -> C end,
 	#{owner := Self} = gun:info(ConnPid),
 	gun:close(ConnPid).
 
 shutdown_reason(_) ->
 	doc("The last connection failure must be propagated."),
-	{ok, Pid} = gun:open("localhost", 12345, #{retry => 0}),
-	Ref = monitor(process, Pid),
-	After = case os:type() of
-		{win32, _} -> 2300;
-		_ -> 300
-	end,
+	{ok, ConnPid} = gun:open("localhost", 12345, #{retry => 0}),
+	Ref = monitor(process, ConnPid),
 	receive
-		{'DOWN', Ref, process, Pid, {shutdown, econnrefused}} ->
-			ok
-	after After ->
-		error(timeout)
+		{'DOWN', Ref, process, ConnPid, {shutdown, econnrefused}} ->
+			gun:close(ConnPid)
 	end.
 
 stream_info_http(_) ->
@@ -561,8 +575,6 @@ do_unix_socket_connect() ->
 	receive
 		{recv, _} ->
 			gun:close(Pid)
-	after 250 ->
-		error(timeout)
 	end.
 
 uppercase_header_name(_) ->
diff --git a/test/gun_test_event_h.erl b/test/gun_test_event_h.erl
new file mode 100644
index 0000000..98b2669
--- /dev/null
+++ b/test/gun_test_event_h.erl
@@ -0,0 +1,65 @@
+%% Copyright (c) 2020, Loïc Hoguin <[email protected]>
+%%
+%% Permission to use, copy, modify, and/or distribute this software for any
+%% purpose with or without fee is hereby granted, provided that the above
+%% copyright notice and this permission notice appear in all copies.
+%%
+%% THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
+%% WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
+%% MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
+%% ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
+%% WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
+%% ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
+%% OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
+
+-module(gun_test_event_h).
+-compile(export_all).
+-compile(nowarn_export_all).
+
+init(Event, State) -> common(?FUNCTION_NAME, Event, State).
+domain_lookup_start(Event, State) -> common(?FUNCTION_NAME, Event, State).
+domain_lookup_end(Event, State) -> common(?FUNCTION_NAME, Event, State).
+connect_start(Event, State) -> common(?FUNCTION_NAME, Event, State).
+connect_end(Event, State) -> common(?FUNCTION_NAME, Event, State).
+tls_handshake_start(Event, State) -> common(?FUNCTION_NAME, Event, State).
+tls_handshake_end(Event, State) -> common(?FUNCTION_NAME, Event, State).
+request_start(Event, State) -> common(?FUNCTION_NAME, Event, State).
+request_headers(Event, State) -> common(?FUNCTION_NAME, Event, State).
+request_end(Event, State) -> common(?FUNCTION_NAME, Event, State).
+push_promise_start(Event, State) -> common(?FUNCTION_NAME, Event, State).
+push_promise_end(Event, State) -> common(?FUNCTION_NAME, Event, State).
+response_start(Event, State) -> common(?FUNCTION_NAME, Event, State).
+response_inform(Event, State) -> common(?FUNCTION_NAME, Event, State).
+response_headers(Event, State) -> common(?FUNCTION_NAME, Event, State).
+response_trailers(Event, State) -> common(?FUNCTION_NAME, Event, State).
+response_end(Event, State) -> common(?FUNCTION_NAME, Event, State).
+ws_upgrade(Event, State) -> common(?FUNCTION_NAME, Event, State).
+ws_recv_frame_start(Event, State) -> common(?FUNCTION_NAME, Event, State).
+ws_recv_frame_header(Event, State) -> common(?FUNCTION_NAME, Event, State).
+ws_recv_frame_end(Event, State) -> common(?FUNCTION_NAME, Event, State).
+ws_send_frame_start(Event, State) -> common(?FUNCTION_NAME, Event, State).
+ws_send_frame_end(Event, State) -> common(?FUNCTION_NAME, Event, State).
+protocol_changed(Event, State) -> common(?FUNCTION_NAME, Event, State).
+transport_changed(Event, State) -> common(?FUNCTION_NAME, Event, State).
+origin_changed(Event, State) -> common(?FUNCTION_NAME, Event, State).
+cancel(Event, State) -> common(?FUNCTION_NAME, Event, State).
+disconnect(Event, State) -> common(?FUNCTION_NAME, Event, State).
+terminate(Event, State) -> common(?FUNCTION_NAME, Event, State).
+
+common(EventType, Event, State=Pid) ->
+	Pid ! {self(), EventType, Event#{
+		ts => erlang:system_time(millisecond)
+	}},
+	State.
+
+receive_event(Pid) ->
+	receive
+		Msg = {Pid, EventType, Event} when is_atom(EventType), is_map(Event) ->
+			Msg
+	end.
+
+receive_event(Pid, EventType) ->
+	receive
+		Msg = {Pid, EventType, Event} when is_map(Event) ->
+			Msg
+	end.