Use LoggerHelpers in HTTP2 tests

test/bandit/http2/plug_test.exs

@@ -4,8 +4,6 @@ defmodule HTTP2PlugTest do
   use ReqHelpers
   use Machete
 
-  import ExUnit.CaptureLog
-
   setup :https_server
   setup :req_h2_client
 
@@ -33,46 +31,38 @@ defmodule HTTP2PlugTest do
   end
 
   describe "error response & logging" do
+    @tag :capture_log
     test "it should return 500 and log when unknown exceptions are raised", context do
-      output =
-        capture_log(fn ->
-          {:ok, response} = Req.get(context.req, url: "/unknown_crasher")
-          assert response.status == 500
-          Process.sleep(100)
-        end)
+      {:ok, response} = Req.get(context.req, url: "/unknown_crasher")
+      assert response.status == 500
 
-      assert output =~ "(RuntimeError) boom"
+      assert %{msg: {:string, msg}} = LoggerHelpers.await_log(:error)
+      assert msg =~ "** (RuntimeError) boom"
     end
 
     def unknown_crasher(_conn) do
       raise "boom"
     end
 
     test "it should return the code and not log when known exceptions are raised", context do
-      output =
-        capture_log(fn ->
-          {:ok, response} = Req.get(context.req, url: "/known_crasher")
-          assert response.status == 418
-          Process.sleep(100)
-        end)
+      {:ok, response} = Req.get(context.req, url: "/known_crasher")
+      assert response.status == 418
 
-      assert output == ""
+      refute LoggerHelpers.await_log(:error)
     end
 
+    @tag :capture_log
     test "it should log known exceptions if so configured", context do
       context =
         context
         |> https_server(http_options: [log_exceptions_with_status_codes: 100..599])
         |> Enum.into(context)
 
-      output =
-        capture_log(fn ->
-          {:ok, response} = Req.get(context.req, url: "/known_crasher", base_url: context.base)
-          assert response.status == 418
-          Process.sleep(100)
-        end)
+      {:ok, response} = Req.get(context.req, url: "/known_crasher", base_url: context.base)
+      assert response.status == 418
 
-      assert output =~ "(SafeError) boom"
+      assert %{msg: {:string, msg}} = LoggerHelpers.await_log(:error)
+      assert msg =~ "** (SafeError) boom"
     end
 
     def known_crasher(_conn) do
@@ -142,6 +132,7 @@ defmodule HTTP2PlugTest do
     conn |> send_resp(200, body)
   end
 
+  @tag :capture_log
   test "reading request body from another process works as expected", context do
     response = Req.post!(context.req, url: "/other_process_body_read", body: "OK")
 
@@ -356,6 +347,7 @@ defmodule HTTP2PlugTest do
     conn |> resp(200, "OK")
   end
 
+  @tag :capture_log
   test "sending a body from another process works as expected", context do
     response = Req.post!(context.req, url: "/other_process_send_body", body: "OK")
 
@@ -392,6 +384,7 @@ defmodule HTTP2PlugTest do
     |> elem(1)
   end
 
+  @tag :capture_log
   test "setting a chunked response from another process works as expected", context do
     response = Req.post!(context.req, url: "/other_process_set_chunk", body: "OK")
 
@@ -412,6 +405,7 @@ defmodule HTTP2PlugTest do
     end
   end
 
+  @tag :capture_log
   test "sending a chunk from another process works as expected", context do
     response = Req.post!(context.req, url: "/other_process_send_chunk", body: "OK")
 
@@ -430,22 +424,20 @@ defmodule HTTP2PlugTest do
     end)
     |> Task.await()
     |> case do
-      :ok -> tap(conn, &chunk(&1, "OK"))
+      :ok ->
+        {:ok, conn} = chunk(conn, "OK")
+        conn
     end
   end
 
   describe "upgrade handling" do
+    @tag :capture_log
     test "raises an ArgumentError on unsupported upgrades", context do
-      errors =
-        capture_log(fn ->
-          {:ok, response} = Req.get(context.req, url: "/upgrade_unsupported")
-          assert response.status == 500
-
-          Process.sleep(100)
-        end)
+      {:ok, response} = Req.get(context.req, url: "/upgrade_unsupported")
+      assert response.status == 500
 
-      assert errors =~
-               "(ArgumentError) upgrade to unsupported not supported by Bandit.Adapter"
+      assert %{msg: {:string, msg}} = LoggerHelpers.await_log(:error)
+      assert msg =~ "** (ArgumentError) upgrade to unsupported not supported by Bandit.Adapter"
     end
 
     def upgrade_unsupported(conn) do
@@ -455,32 +447,28 @@ defmodule HTTP2PlugTest do
     end
   end
 
+  @tag :capture_log
   test "raises a Plug.Conn.NotSentError if nothing was set in the conn", context do
-    errors =
-      capture_log(fn ->
-        {:ok, response} = Req.get(context.req, url: "/noop")
-        assert response.status == 500
+    {:ok, response} = Req.get(context.req, url: "/noop")
+    assert response.status == 500
 
-        Process.sleep(100)
-      end)
+    assert %{msg: {:string, msg}} = LoggerHelpers.await_log(:error)
 
-    assert errors =~
-             "(Plug.Conn.NotSentError) a response was neither set nor sent from the connection"
+    assert msg =~
+             "** (Plug.Conn.NotSentError) a response was neither set nor sent from the connection"
   end
 
   def noop(conn), do: conn
 
+  @tag :capture_log
   test "raises an error if the conn returns garbage", context do
-    errors =
-      capture_log(fn ->
-        {:ok, response} = Req.get(context.req, url: "/garbage")
-        assert response.status == 500
+    {:ok, response} = Req.get(context.req, url: "/garbage")
+    assert response.status == 500
 
-        Process.sleep(100)
-      end)
+    assert %{msg: {:string, msg}} = LoggerHelpers.await_log(:error)
 
-    assert errors =~
-             "(RuntimeError) Expected Elixir.HTTP2PlugTest.call/2 to return %Plug.Conn{} but got: :boom"
+    assert msg =~
+             "** (RuntimeError) Expected Elixir.HTTP2PlugTest.call/2 to return %Plug.Conn{} but got: :boom"
   end
 
   def garbage(_conn), do: :boom
@@ -519,16 +507,13 @@ defmodule HTTP2PlugTest do
     |> send_file(200, @large_file_path, 0, :all)
   end
 
+  @tag :capture_log
   test "errors out if asked to read beyond the file", context do
-    errors =
-      capture_log(fn ->
-        {:ok, response} = Req.get(context.req, url: "/send_file?offset=1&length=3000")
-        assert response.status == 500
-
-        Process.sleep(100)
-      end)
+    {:ok, response} = Req.get(context.req, url: "/send_file?offset=1&length=3000")
+    assert response.status == 500
 
-    assert errors =~ "(RuntimeError) Cannot read 3000 bytes starting at 1"
+    assert %{msg: {:string, msg}} = LoggerHelpers.await_log(:error)
+    assert msg =~ "** (RuntimeError) Cannot read 3000 bytes starting at 1"
   end
 
   def send_file(conn) do
@@ -543,6 +528,7 @@ defmodule HTTP2PlugTest do
     )
   end
 
+  @tag :capture_log
   test "sending a file from another process works as expected", context do
     response = Req.post!(context.req, url: "/other_process_send_file", body: "OK")
 
@@ -699,6 +685,7 @@ defmodule HTTP2PlugTest do
     conn |> send_resp(200, "Informer")
   end
 
+  @tag :capture_log
   test "sending an inform response from another process works as expected", context do
     response = Req.post!(context.req, url: "/other_process_send_inform", body: "OK")
 
@@ -746,24 +733,15 @@ defmodule HTTP2PlugTest do
   end
 
   test "silently accepts EXIT messages from normally terminating spawned processes", context do
-    errors =
-      capture_log(fn ->
-        Req.get!(context.req, url: "/spawn_child")
-
-        # Let the backing process see & handle the handle_info EXIT message
-        Process.sleep(100)
-      end)
+    response = Req.get!(context.req, url: "/spawn_child")
+    assert response.status == 204
 
-    # The return value here isn't relevant, since the HTTP call is done within
-    # a single Task call & may complete before the spawned process exits. Look
-    # at the logged errors instead
-    assert errors == ""
+    refute LoggerHelpers.await_log(:error)
   end
 
   def spawn_child(conn) do
     spawn_link(fn -> exit(:normal) end)
-    # Ensure that the spawned process has a chance to exit
-    Process.sleep(100)
+    Process.sleep(10)
     send_resp(conn, 204, "")
   end
 
@@ -933,81 +911,64 @@ defmodule HTTP2PlugTest do
               }}
     end
 
+    @tag :capture_log
     test "it should send `stop` events for malformed requests", context do
-      output =
-        capture_log(fn ->
-          socket = SimpleH2Client.setup_connection(context)
-
-          # Take uppercase header example from H2Spec
-          headers =
-            <<130, 135, 68, 137, 98, 114, 209, 65, 226, 240, 123, 40, 147, 65, 139, 8, 157, 92,
-              11, 129, 112, 220, 109, 199, 26, 127, 64, 6, 88, 45, 84, 69, 83, 84, 2, 111, 107>>
+      socket = SimpleH2Client.setup_connection(context)
 
-          SimpleH2Client.send_frame(socket, 1, 5, 1, headers)
+      # Take uppercase header example from H2Spec
+      headers =
+        <<130, 135, 68, 137, 98, 114, 209, 65, 226, 240, 123, 40, 147, 65, 139, 8, 157, 92, 11,
+          129, 112, 220, 109, 199, 26, 127, 64, 6, 88, 45, 84, 69, 83, 84, 2, 111, 107>>
 
-          assert TelemetryHelpers.await_event([:bandit, :request, :stop])
-                 ~> {[:bandit, :request, :stop],
-                  %{monotonic_time: integer(), duration: integer()},
-                  %{
-                    plug: {__MODULE__, []},
-                    connection_telemetry_span_context: reference(),
-                    telemetry_span_context: reference(),
-                    error: string()
-                  }}
-        end)
+      SimpleH2Client.send_frame(socket, 1, 5, 1, headers)
 
-      assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received uppercase header"
+      assert TelemetryHelpers.await_event([:bandit, :request, :stop])
+             ~> {[:bandit, :request, :stop], %{monotonic_time: integer(), duration: integer()},
+              %{
+                plug: {__MODULE__, []},
+                connection_telemetry_span_context: reference(),
+                telemetry_span_context: reference(),
+                error: string()
+              }}
     end
 
+    @tag :capture_log
     test "it should send `exception` events for raising requests", context do
-      output =
-        capture_log(fn ->
-          Req.get(context.req, url: "/raise_error")
-
-          assert TelemetryHelpers.await_event([:bandit, :request, :exception])
-                 ~> {[:bandit, :request, :exception], %{monotonic_time: integer()},
-                  %{
-                    connection_telemetry_span_context: reference(),
-                    telemetry_span_context: reference(),
-                    conn: struct_like(Plug.Conn, []),
-                    plug: {__MODULE__, []},
-                    kind: :exit,
-                    exception: %RuntimeError{message: "boom"},
-                    stacktrace: list()
-                  }}
-        end)
-
-      assert output =~ "(RuntimeError) boom"
+      Req.get(context.req, url: "/raise_error")
+
+      assert TelemetryHelpers.await_event([:bandit, :request, :exception])
+             ~> {[:bandit, :request, :exception], %{monotonic_time: integer()},
+              %{
+                connection_telemetry_span_context: reference(),
+                telemetry_span_context: reference(),
+                conn: struct_like(Plug.Conn, []),
+                plug: {__MODULE__, []},
+                kind: :exit,
+                exception: %RuntimeError{message: "boom"},
+                stacktrace: list()
+              }}
     end
 
     def raise_error(_conn) do
       raise "boom"
     end
 
+    @tag :capture_log
     test "it should not send `exception` events for throwing requests", context do
-      output =
-        capture_log(fn ->
-          Req.get!(context.req, url: "/uncaught_throw")
-
-          refute TelemetryHelpers.await_event([:bandit, :request, :exception])
-        end)
+      Req.get!(context.req, url: "/uncaught_throw")
 
-      assert output =~ "(throw) \"thrown\""
+      refute TelemetryHelpers.await_event([:bandit, :request, :exception])
     end
 
     def uncaught_throw(_conn) do
       throw("thrown")
     end
 
+    @tag :capture_log
     test "it should not send `exception` events for exiting requests", context do
-      output =
-        capture_log(fn ->
-          Req.get!(context.req, url: "/uncaught_exit")
-
-          refute TelemetryHelpers.await_event([:bandit, :request, :exception])
-        end)
+      Req.get!(context.req, url: "/uncaught_exit")
 
-      assert output =~ "(exit) \"exited\""
+      refute TelemetryHelpers.await_event([:bandit, :request, :exception])
     end
 
     def uncaught_exit(_conn) do