diff --git a/test/bandit/http2/plug_test.exs b/test/bandit/http2/plug_test.exs index bfb79e19..5890024e 100644 --- a/test/bandit/http2/plug_test.exs +++ b/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,15 +31,13 @@ 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 @@ -49,30 +45,24 @@ defmodule HTTP2PlugTest do 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 diff --git a/test/bandit/http2/protocol_test.exs b/test/bandit/http2/protocol_test.exs index 94c00d06..7143bcf1 100644 --- a/test/bandit/http2/protocol_test.exs +++ b/test/bandit/http2/protocol_test.exs @@ -3,7 +3,6 @@ defmodule HTTP2ProtocolTest do use ServerHelpers import Bitwise - import ExUnit.CaptureLog setup :https_server @@ -42,8 +41,7 @@ defmodule HTTP2ProtocolTest do end describe "errors and unexpected frames" do - test "it should silently ignore client closes", - context do + test "it should silently ignore client closes", context do socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) SimpleH2Client.send_goaway(socket, 0, 0) @@ -51,92 +49,91 @@ defmodule HTTP2ProtocolTest do Process.sleep(100) end + @tag :capture_log test "it should ignore unknown frame types", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) - SimpleH2Client.send_frame(socket, 254, 0, 0, <<>>) - assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - end) + socket = SimpleH2Client.setup_connection(context) + SimpleH2Client.send_frame(socket, 254, 0, 0, <<>>) + assert SimpleH2Client.connection_alive?(socket) # We can't match on the entire message since it's ordered differently on different OTPs - assert output =~ "Unknown frame" + assert %{msg: {:string, msg}} = LoggerHelpers.await_log(:warning) + assert msg =~ "Unknown frame" end + @tag :capture_log test "it should shut down the connection gracefully and log when encountering a connection error", context do socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) - errors = - capture_log(fn -> - # Send a bogus SETTINGS frame - SimpleH2Client.send_frame(socket, 4, 0, 1, <<>>) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + # Send a bogus SETTINGS frame + SimpleH2Client.send_frame(socket, 4, 0, 1, <<>>) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert errors =~ - "(Bandit.HTTP2.Errors.ConnectionError) Invalid SETTINGS frame (RFC9113§6.5)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) Invalid SETTINGS frame (RFC9113§6.5)"} + } = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "it should shut down the connection gracefully and log when encountering a connection error related to a stream", context do socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) - errors = - capture_log(fn -> - # Send a WINDOW_UPDATE on an idle stream - SimpleH2Client.send_window_update(socket, 1, 1234) + # Send a WINDOW_UPDATE on an idle stream + SimpleH2Client.send_window_update(socket, 1, 1234) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 1, 1} - assert errors =~ - "[error] ** (Bandit.HTTP2.Errors.ConnectionError) Received WINDOW_UPDATE in idle state" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) Received WINDOW_UPDATE in idle state"} + } = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "it should shut down the stream gracefully and log when encountering a stream error", context do socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) + # Send trailers with pseudo headers + {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) + SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - errors = - capture_log(fn -> - # Send trailers with pseudo headers - {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) - SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) - - assert errors =~ - "[error] ** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers"} + } = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "stream errors are short logged by default", context do socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) - output = - capture_log(fn -> - # Send trailers with pseudo headers - {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) - SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + # Send trailers with pseudo headers + {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) + SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ - "[error] ** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" - - # Make sure we don't log a stacktrace - refute output =~ "lib/bandit/pipeline.ex:" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers"} + } = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "stream errors are verbosely logged if so configured", context do context = context @@ -146,20 +143,15 @@ defmodule HTTP2ProtocolTest do socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) - output = - capture_log(fn -> - # Send trailers with pseudo headers - {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) - SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + # Send trailers with pseudo headers + {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) + SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ - "[error] ** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" + assert %{msg: {:string, msg}} = LoggerHelpers.await_log(:error) - # Make sure we log a stacktrace - assert output =~ "lib/bandit/pipeline.ex:" + assert msg =~ "** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" + assert msg =~ "lib/bandit/pipeline.ex:" end test "stream errors are not logged if so configured", context do @@ -171,23 +163,19 @@ defmodule HTTP2ProtocolTest do socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) - output = - capture_log(fn -> - # Send trailers with pseudo headers - {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) - SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + # Send trailers with pseudo headers + {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) + SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output == "" + refute LoggerHelpers.await_log(:error) end test "it should shut down the connection after read timeout has been reached with no initial data sent", context do context = https_server(context, thousand_island_options: [read_timeout: 100]) socket = SimpleH2Client.tls_client(context) - Process.sleep(150) + Process.sleep(110) assert Transport.recv(socket, 0) == {:error, :closed} end @@ -196,43 +184,44 @@ defmodule HTTP2ProtocolTest do context = https_server(context, thousand_island_options: [read_timeout: 100]) socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) - Process.sleep(150) + Process.sleep(110) assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 0} end + @tag :capture_log test "returns a connection error if too many requests are sent", context do - output = - capture_log(fn -> - context = https_server(context, http_2_options: [max_requests: 3]) - socket = SimpleH2Client.setup_connection(context) - port = context[:port] + context = https_server(context, http_2_options: [max_requests: 3]) + socket = SimpleH2Client.setup_connection(context) + port = context[:port] - {:ok, send_ctx} = - SimpleH2Client.send_simple_headers(socket, 1, :get, "/body_response", port) + {:ok, send_ctx} = + SimpleH2Client.send_simple_headers(socket, 1, :get, "/body_response", port) - {:ok, 1, false, _, recv_ctx} = SimpleH2Client.recv_headers(socket) - assert SimpleH2Client.recv_body(socket) == {:ok, 1, true, "OK"} + {:ok, 1, false, _, recv_ctx} = SimpleH2Client.recv_headers(socket) + assert SimpleH2Client.recv_body(socket) == {:ok, 1, true, "OK"} - {:ok, send_ctx} = - SimpleH2Client.send_simple_headers(socket, 3, :get, "/body_response", port, send_ctx) + {:ok, send_ctx} = + SimpleH2Client.send_simple_headers(socket, 3, :get, "/body_response", port, send_ctx) - {:ok, 3, false, _, recv_ctx} = SimpleH2Client.recv_headers(socket, recv_ctx) - assert SimpleH2Client.recv_body(socket) == {:ok, 3, true, "OK"} + {:ok, 3, false, _, recv_ctx} = SimpleH2Client.recv_headers(socket, recv_ctx) + assert SimpleH2Client.recv_body(socket) == {:ok, 3, true, "OK"} - {:ok, send_ctx} = - SimpleH2Client.send_simple_headers(socket, 5, :get, "/body_response", port, send_ctx) + {:ok, send_ctx} = + SimpleH2Client.send_simple_headers(socket, 5, :get, "/body_response", port, send_ctx) - {:ok, 5, false, _, _recv_ctx} = SimpleH2Client.recv_headers(socket, recv_ctx) - assert SimpleH2Client.recv_body(socket) == {:ok, 5, true, "OK"} + {:ok, 5, false, _, _recv_ctx} = SimpleH2Client.recv_headers(socket, recv_ctx) + assert SimpleH2Client.recv_body(socket) == {:ok, 5, true, "OK"} - {:ok, _send_ctx} = - SimpleH2Client.send_simple_headers(socket, 7, :get, "/body_response", port, send_ctx) + {:ok, _send_ctx} = + SimpleH2Client.send_simple_headers(socket, 7, :get, "/body_response", port, send_ctx) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 5, 7} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 5, 7} - assert output =~ "(Bandit.HTTP2.Errors.ConnectionError) Connection count exceeded" + assert %{ + msg: + {:string, "** (Bandit.HTTP2.Errors.ConnectionError) Connection count exceeded"} + } = + LoggerHelpers.await_log(:error) end end @@ -1048,19 +1037,20 @@ defmodule HTTP2ProtocolTest do conn |> send_resp(200, body) end + @tag :capture_log test "rejects DATA frames received on an idle stream", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - SimpleH2Client.send_body(socket, 1, true, "OK") - {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) + SimpleH2Client.send_body(socket, 1, true, "OK") + {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.ConnectionError) Received DATA in idle state" + assert %{ + msg: + {:string, "** (Bandit.HTTP2.Errors.ConnectionError) Received DATA in idle state"} + } = + LoggerHelpers.await_log(:error) end test "reads a one frame body if one frame is sent", context do @@ -1120,131 +1110,133 @@ defmodule HTTP2ProtocolTest do end # Error case for content-length as defined in https://www.rfc-editor.org/rfc/rfc9112.html#section-6.3-2.5 + @tag :capture_log test "returns a stream error if content length contains non-matching values", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "POST"}, - {":path", "/expect_body_with_multiple_content_length"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"}, - {"content-length", "8000,8001,8000"} - ] + headers = [ + {":method", "POST"}, + {":path", "/expect_body_with_multiple_content_length"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"}, + {"content-length", "8000,8001,8000"} + ] - SimpleH2Client.send_headers(socket, 1, false, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - end) + SimpleH2Client.send_headers(socket, 1, false, headers) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} + assert SimpleH2Client.connection_alive?(socket) - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)"} + } = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if sent content-length is negative", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "POST"}, - {":path", "/echo"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"}, - {"content-length", "-321"} - ] + headers = [ + {":method", "POST"}, + {":path", "/echo"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"}, + {"content-length", "-321"} + ] - SimpleH2Client.send_headers(socket, 1, false, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - end) + SimpleH2Client.send_headers(socket, 1, false, headers) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} + assert SimpleH2Client.connection_alive?(socket) - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if sent content length is non-integer", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "POST"}, - {":path", "/echo"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"}, - {"content-length", "foo"} - ] + headers = [ + {":method", "POST"}, + {":path", "/echo"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"}, + {"content-length", "foo"} + ] - SimpleH2Client.send_headers(socket, 1, false, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - end) + SimpleH2Client.send_headers(socket, 1, false, headers) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} + assert SimpleH2Client.connection_alive?(socket) - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if sent content-length doesn't match sent data", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "POST"}, - {":path", "/echo"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"}, - {"content-length", "3"} - ] + headers = [ + {":method", "POST"}, + {":path", "/echo"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"}, + {"content-length", "3"} + ] - SimpleH2Client.send_headers(socket, 1, false, headers) - SimpleH2Client.send_body(socket, 1, false, "OK") - SimpleH2Client.send_body(socket, 1, true, "OK") + SimpleH2Client.send_headers(socket, 1, false, headers) + SimpleH2Client.send_body(socket, 1, false, "OK") + SimpleH2Client.send_body(socket, 1, true, "OK") - {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) - {:ok, 1, _} = SimpleH2Client.recv_window_update(socket) + {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) + {:ok, 1, _} = SimpleH2Client.recv_window_update(socket) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} + assert SimpleH2Client.connection_alive?(socket) - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) Received END_STREAM with byte still pending" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) Received END_STREAM with byte still pending"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "rejects DATA frames received on a zero stream id", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - SimpleH2Client.send_body(socket, 0, true, "OK") + SimpleH2Client.send_body(socket, 0, true, "OK") - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) DATA frame with zero stream_id (RFC9113§6.1)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) DATA frame with zero stream_id (RFC9113§6.1)"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "rejects DATA frames received on an invalid stream id", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - SimpleH2Client.send_body(socket, 2, true, "OK") + SimpleH2Client.send_body(socket, 2, true, "OK") - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ "(Bandit.HTTP2.Errors.ConnectionError) Received invalid stream identifier" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) Received invalid stream identifier"} + } = LoggerHelpers.await_log(:error) end end @@ -1413,200 +1405,192 @@ defmodule HTTP2ProtocolTest do assert SimpleH2Client.connection_alive?(socket) end + @tag :capture_log test "accepts HEADER frames sent as trailers", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) - - {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) - SimpleH2Client.send_body(socket, 1, false, "OK") - SimpleH2Client.send_headers(socket, 1, true, [{"x-trailer", "trailer"}], ctx) + socket = SimpleH2Client.setup_connection(context) - {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) - {:ok, 1, _} = SimpleH2Client.recv_window_update(socket) + {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) + SimpleH2Client.send_body(socket, 1, false, "OK") + SimpleH2Client.send_headers(socket, 1, true, [{"x-trailer", "trailer"}], ctx) - assert SimpleH2Client.successful_response?(socket, 1, false) - assert SimpleH2Client.recv_body(socket) == {:ok, 1, true, "OK"} + {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) + {:ok, 1, _} = SimpleH2Client.recv_window_update(socket) - assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - end) + assert SimpleH2Client.successful_response?(socket, 1, false) + assert SimpleH2Client.recv_body(socket) == {:ok, 1, true, "OK"} - assert output =~ "Ignoring trailers [{\"x-trailer\", \"trailer\"}]" + assert SimpleH2Client.connection_alive?(socket) end + @tag :capture_log test "rejects HEADER frames sent as trailers that contain pseudo headers", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) - SimpleH2Client.send_body(socket, 1, false, "OK") + {:ok, ctx} = SimpleH2Client.send_simple_headers(socket, 1, :post, "/echo", context.port) + SimpleH2Client.send_body(socket, 1, false, "OK") - {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) - {:ok, 1, _} = SimpleH2Client.recv_window_update(socket) + {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) + {:ok, 1, _} = SimpleH2Client.recv_window_update(socket) - SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) + SimpleH2Client.send_headers(socket, 1, true, [{":path", "/foo"}], ctx) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} + assert SimpleH2Client.connection_alive?(socket) - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers"} + } = LoggerHelpers.await_log(:error) end - test "closes with an error when receiving a zero stream ID", - context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + @tag :capture_log + test "closes with an error when receiving a zero stream ID", context do + socket = SimpleH2Client.setup_connection(context) - SimpleH2Client.send_simple_headers(socket, 0, :get, "/echo", context.port) + SimpleH2Client.send_simple_headers(socket, 0, :get, "/echo", context.port) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) HEADERS frame with zero stream_id (RFC9113§6.2)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) HEADERS frame with zero stream_id (RFC9113§6.2)"} + } = LoggerHelpers.await_log(:error) end - test "closes with an error when receiving an even stream ID", - context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + @tag :capture_log + test "closes with an error when receiving an even stream ID", context do + socket = SimpleH2Client.setup_connection(context) - SimpleH2Client.send_simple_headers(socket, 2, :get, "/echo", context.port) + SimpleH2Client.send_simple_headers(socket, 2, :get, "/echo", context.port) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ "(Bandit.HTTP2.Errors.ConnectionError) Received invalid stream identifier" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) Received invalid stream identifier"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "closes with an error on a header frame with undecompressable header block", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - SimpleH2Client.send_frame(socket, 1, 0x2C, 1, <<2, 1::1, 12::31, 34, 1, 2, 3, 4, 5>>) + SimpleH2Client.send_frame(socket, 1, 0x2C, 1, <<2, 1::1, 12::31, 34, 1, 2, 3, 4, 5>>) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 9} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 9} - assert output =~ "(Bandit.HTTP2.Errors.ConnectionError) Header decode error" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.ConnectionError) Header decode error"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if sent headers with uppercase names", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - # Take 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>> + # Take 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>> - SimpleH2Client.send_frame(socket, 1, 5, 1, headers) + SimpleH2Client.send_frame(socket, 1, 5, 1, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received uppercase header" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Received uppercase header"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if sent headers with invalid pseudo headers", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", "/"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"}, - {":bogus", "bogus"} - ] + headers = [ + {":method", "HEAD"}, + {":path", "/"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"}, + {":bogus", "bogus"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received invalid pseudo header" + assert %{ + msg: + {:string, "** (Bandit.HTTP2.Errors.StreamError) Received invalid pseudo header"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if sent headers with response pseudo headers", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", "/"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"}, - {":status", "200"} - ] + headers = [ + {":method", "HEAD"}, + {":path", "/"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"}, + {":status", "200"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received invalid pseudo header" + assert %{ + msg: + {:string, "** (Bandit.HTTP2.Errors.StreamError) Received invalid pseudo header"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if pseudo headers appear after regular ones", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", "/"}, - {":scheme", "https"}, - {"regular-header", "boring"}, - {":authority", "localhost:#{context.port}"} - ] + headers = [ + {":method", "HEAD"}, + {":path", "/"}, + {":scheme", "https"}, + {"regular-header", "boring"}, + {":authority", "localhost:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) Received pseudo headers after regular one" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) Received pseudo headers after regular one"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns an error if (almost) any hop-by-hop headers are present", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", "/"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"}, - {"connection", "close"} - ] + headers = [ + {":method", "HEAD"}, + {":path", "/"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"}, + {"connection", "close"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received connection-specific header" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) Received connection-specific header"} + } = LoggerHelpers.await_log(:error) end test "accepts TE header with a value of trailer", context do @@ -1625,173 +1609,157 @@ defmodule HTTP2ProtocolTest do assert SimpleH2Client.successful_response?(socket, 1, true) end + @tag :capture_log test "returns an error if TE header is present with a value other than trailers", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", "/"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"}, - {"te", "trailers, deflate"} - ] + headers = [ + {":method", "HEAD"}, + {":path", "/"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"}, + {"te", "trailers, deflate"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received invalid TE header" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Received invalid TE header"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if :method pseudo header is missing", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":path", "/"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"} - ] + headers = [ + {":path", "/"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Expected 1 :method headers" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :method headers"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if multiple :method pseudo headers are received", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":method", "HEAD"}, - {":path", "/"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"} - ] + headers = [ + {":method", "HEAD"}, + {":method", "HEAD"}, + {":path", "/"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Expected 1 :method headers" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :method headers"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if :scheme pseudo header is missing", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", "/"}, - {":authority", "localhost:#{context.port}"} - ] + headers = [ + {":method", "HEAD"}, + {":path", "/"}, + {":authority", "localhost:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Expected 1 :scheme headers" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :scheme headers"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if multiple :scheme pseudo headers are received", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", "/"}, - {":scheme", "https"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"} - ] + headers = [ + {":method", "HEAD"}, + {":path", "/"}, + {":scheme", "https"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Expected 1 :scheme headers" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :scheme headers"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if :path pseudo header is missing", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"} - ] + headers = [ + {":method", "HEAD"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received empty :path" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Received empty :path"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if multiple :path pseudo headers are received", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", "/"}, - {":path", "/"}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"} - ] + headers = [ + {":method", "HEAD"}, + {":path", "/"}, + {":path", "/"}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Expected 1 :path headers" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :path headers"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns a stream error if :path pseudo headers is empty", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "HEAD"}, - {":path", ""}, - {":scheme", "https"}, - {":authority", "localhost:#{context.port}"} - ] + headers = [ + {":method", "HEAD"}, + {":path", ""}, + {":scheme", "https"}, + {":authority", "localhost:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Path does not start with /" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Path does not start with /"}} = + LoggerHelpers.await_log(:error) end test "combines Cookie headers per RFC9113§8.2.3", context do @@ -1885,27 +1853,27 @@ defmodule HTTP2ProtocolTest do assert SimpleH2Client.recv_body(socket) == {:ok, 3, true, "OK"} end + @tag :capture_log test "returns a stream error if sent header block is too large", context do - output = - capture_log(fn -> - context = https_server(context, http_2_options: [max_header_block_size: 40]) - socket = SimpleH2Client.setup_connection(context) + context = https_server(context, http_2_options: [max_header_block_size: 40]) + socket = SimpleH2Client.setup_connection(context) - headers = - [ - {":method", "HEAD"}, - {":path", "/"}, - {":scheme", "https"}, - {":authority", "localhost:#{context[:port]}"} - ] ++ for i <- 1..37, do: {"header#{i}", "foo"} + headers = + [ + {":method", "HEAD"}, + {":path", "/"}, + {":scheme", "https"}, + {":authority", "localhost:#{context[:port]}"} + ] ++ for i <- 1..37, do: {"header#{i}", "foo"} - SimpleH2Client.send_headers(socket, 1, true, headers) + SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ "(Bandit.HTTP2.Errors.ConnectionError) Received overlong headers" + assert %{ + msg: + {:string, "** (Bandit.HTTP2.Errors.ConnectionError) Received overlong headers"} + } = LoggerHelpers.await_log(:error) end end @@ -1942,19 +1910,19 @@ defmodule HTTP2ProtocolTest do assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 1, 0} end + @tag :capture_log test "sends RST_FRAME with internal error if we don't set a response with a closed client", context do socket = SimpleH2Client.setup_connection(context) - errors = - capture_log(fn -> - SimpleH2Client.send_simple_headers(socket, 1, :get, "/no_response_get", context.port) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 2} - Process.sleep(100) - end) + SimpleH2Client.send_simple_headers(socket, 1, :get, "/no_response_get", context.port) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 2} - assert errors =~ - "[error] ** (Bandit.HTTP2.Errors.StreamError) Terminating stream in remote_closed state" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) Terminating stream in remote_closed state"} + } = LoggerHelpers.await_log(:error) end def no_response_get(conn) do @@ -1965,19 +1933,19 @@ defmodule HTTP2ProtocolTest do %{conn | state: :sent} end + @tag :capture_log test "sends RST_FRAME with internal error if we don't set a response with an open client", context do socket = SimpleH2Client.setup_connection(context) - errors = - capture_log(fn -> - SimpleH2Client.send_simple_headers(socket, 1, :post, "/no_response_post", context.port) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 2} - Process.sleep(100) - end) + SimpleH2Client.send_simple_headers(socket, 1, :post, "/no_response_post", context.port) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 2} - assert errors =~ - "[error] ** (Bandit.HTTP2.Errors.StreamError) Terminating stream in open state" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.StreamError) Terminating stream in open state"} + } = LoggerHelpers.await_log(:error) end def no_response_post(conn) do @@ -1986,50 +1954,51 @@ defmodule HTTP2ProtocolTest do %{conn | state: :sent} end + @tag :capture_log test "rejects RST_STREAM frames received on an idle stream", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - SimpleH2Client.send_rst_stream(socket, 1, 0) + SimpleH2Client.send_rst_stream(socket, 1, 0) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.ConnectionError) Received RST_STREAM in idle state" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) Received RST_STREAM in idle state"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "raises an error upon receipt of an RST_STREAM frame during reading", context do socket = SimpleH2Client.setup_connection(context) - errors = - capture_log(fn -> - SimpleH2Client.send_simple_headers(socket, 1, :post, "/expect_reset", context.port) - SimpleH2Client.send_rst_stream(socket, 1, 99) - Process.sleep(100) - end) + SimpleH2Client.send_simple_headers(socket, 1, :post, "/expect_reset", context.port) + SimpleH2Client.send_rst_stream(socket, 1, 99) - assert errors =~ - "[error] ** (Bandit.TransportError) Received RST_STREAM from client: unknown (99)" + assert %{ + msg: + {:string, + "** (Bandit.TransportError) Received RST_STREAM from client: unknown (99)"} + } = LoggerHelpers.await_log(:error) end def expect_reset(conn) do read_body(conn) end + @tag :capture_log test "raises an error upon receipt of an RST_STREAM frame during writing", context do socket = SimpleH2Client.setup_connection(context) - errors = - capture_log(fn -> - SimpleH2Client.send_simple_headers(socket, 1, :get, "/write_after_delay", context.port) - SimpleH2Client.send_rst_stream(socket, 1, 99) - Process.sleep(200) - end) + SimpleH2Client.send_simple_headers(socket, 1, :get, "/write_after_delay", context.port) + SimpleH2Client.send_rst_stream(socket, 1, 99) - assert errors =~ - "[error] ** (Bandit.TransportError) Received RST_STREAM from client: unknown (99)" + assert %{ + msg: + {:string, + "** (Bandit.TransportError) Received RST_STREAM from client: unknown (99)"} + } = LoggerHelpers.await_log(:error) end def write_after_delay(conn) do @@ -2041,28 +2010,20 @@ defmodule HTTP2ProtocolTest do context do socket = SimpleH2Client.setup_connection(context) - errors = - capture_log(fn -> - SimpleH2Client.send_simple_headers(socket, 1, :get, "/expect_chunk_error", context.port) - SimpleH2Client.send_rst_stream(socket, 1, 0) - Process.sleep(200) - end) + SimpleH2Client.send_simple_headers(socket, 1, :get, "/expect_chunk_error", context.port) + SimpleH2Client.send_rst_stream(socket, 1, 0) - assert errors == "" + refute LoggerHelpers.await_log(:error) end test "considers :cancel RST_STREAM frame as a normal closure during chunk writing", context do socket = SimpleH2Client.setup_connection(context) - errors = - capture_log(fn -> - SimpleH2Client.send_simple_headers(socket, 1, :get, "/expect_chunk_error", context.port) - SimpleH2Client.send_rst_stream(socket, 1, 8) - Process.sleep(200) - end) + SimpleH2Client.send_simple_headers(socket, 1, :get, "/expect_chunk_error", context.port) + SimpleH2Client.send_rst_stream(socket, 1, 8) - assert errors == "" + refute LoggerHelpers.await_log(:error) end def expect_chunk_error(conn) do @@ -2083,19 +2044,19 @@ defmodule HTTP2ProtocolTest do end describe "PUSH_PROMISE frames" do + @tag :capture_log test "the server should reject any received PUSH_PROMISE frames", context do - output = - capture_log(fn -> - socket = SimpleH2Client.tls_client(context) - SimpleH2Client.exchange_prefaces(socket) - SimpleH2Client.send_frame(socket, 5, 0, 1, <<0, 0, 0, 3, 1, 2, 3>>) + socket = SimpleH2Client.tls_client(context) + SimpleH2Client.exchange_prefaces(socket) + SimpleH2Client.send_frame(socket, 5, 0, 1, <<0, 0, 0, 3, 1, 2, 3>>) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) PUSH_PROMISE frame received (RFC9113§8.4)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) PUSH_PROMISE frame received (RFC9113§8.4)"} + } = LoggerHelpers.await_log(:error) end end @@ -2433,59 +2394,59 @@ defmodule HTTP2ProtocolTest do end describe "CONTINUATION frames" do + @tag :capture_log test "rejects non-CONTINUATION frames received when end_headers is false", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - <> = - headers_for_header_read_test(context) + <> = + headers_for_header_read_test(context) - SimpleH2Client.send_frame(socket, 1, 1, 1, header1) - SimpleH2Client.send_frame(socket, 6, 0, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>) + SimpleH2Client.send_frame(socket, 1, 1, 1, header1) + SimpleH2Client.send_frame(socket, 6, 0, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) Expected CONTINUATION frame (RFC9113§6.10)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) Expected CONTINUATION frame (RFC9113§6.10)"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "rejects non-CONTINUATION frames received when from other streams", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - <> = - headers_for_header_read_test(context) + <> = + headers_for_header_read_test(context) - SimpleH2Client.send_frame(socket, 1, 1, 1, header1) - SimpleH2Client.send_frame(socket, 9, 0, 2, header2) + SimpleH2Client.send_frame(socket, 1, 1, 1, header1) + SimpleH2Client.send_frame(socket, 9, 0, 2, header2) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) Expected CONTINUATION frame (RFC9113§6.10)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) Expected CONTINUATION frame (RFC9113§6.10)"} + } = LoggerHelpers.await_log(:error) end + @tag :capture_log test "rejects CONTINUATION frames received when not expected", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = headers_for_header_read_test(context) + headers = headers_for_header_read_test(context) - SimpleH2Client.send_frame(socket, 9, 4, 1, headers) + SimpleH2Client.send_frame(socket, 9, 4, 1, headers) - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) Received unexpected CONTINUATION frame (RFC9113§6.10)" + assert %{ + msg: + {:string, + "** (Bandit.HTTP2.Errors.ConnectionError) Received unexpected CONTINUATION frame (RFC9113§6.10)"} + } = LoggerHelpers.await_log(:error) end end @@ -2541,23 +2502,23 @@ defmodule HTTP2ProtocolTest do assert Jason.decode!(body)["host"] == "banana" end + @tag :capture_log test "sends 400 if no host header set", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "GET"}, - {":path", "/echo_components"}, - {":scheme", "https"} - ] + headers = [ + {":method", "GET"}, + {":path", "/echo_components"}, + {":scheme", "https"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) - assert {:ok, 1, true, [{":status", "400"} | _], _} = SimpleH2Client.recv_headers(socket) - Process.sleep(100) - end) + SimpleH2Client.send_headers(socket, 1, true, headers) + assert {:ok, 1, true, [{":status", "400"} | _], _} = SimpleH2Client.recv_headers(socket) - assert output =~ "(Bandit.HTTPError) Unable to obtain host and port: No host header" + assert %{ + msg: + {:string, "** (Bandit.HTTPError) Unable to obtain host and port: No host header"} + } = LoggerHelpers.await_log(:error) end test "derives port from host header", context do @@ -2612,24 +2573,22 @@ defmodule HTTP2ProtocolTest do assert Jason.decode!(body)["port"] == 1234 end + @tag :capture_log test "sends 400 if port cannot be parsed from host header", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "GET"}, - {":path", "/echo_components"}, - {":scheme", "https"}, - {"host", "banana:-1234"} - ] + headers = [ + {":method", "GET"}, + {":path", "/echo_components"}, + {":scheme", "https"}, + {"host", "banana:-1234"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) - assert {:ok, 1, true, [{":status", "400"} | _], _} = SimpleH2Client.recv_headers(socket) - Process.sleep(100) - end) + SimpleH2Client.send_headers(socket, 1, true, headers) + assert {:ok, 1, true, [{":status", "400"} | _], _} = SimpleH2Client.recv_headers(socket) - assert output =~ "(Bandit.HTTPError) Header contains invalid port" + assert %{msg: {:string, "** (Bandit.HTTPError) Header contains invalid port"}} = + LoggerHelpers.await_log(:error) end test "derives port from schema default if no port specified in host header", context do @@ -2747,44 +2706,40 @@ defmodule HTTP2ProtocolTest do ) end + @tag :capture_log test "returns stream error if a non-absolute path is send", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "GET"}, - {":path", "/../non_absolute_path"}, - {":scheme", "https"}, - {"host", "banana:#{context.port}"} - ] + headers = [ + {":method", "GET"}, + {":path", "/../non_absolute_path"}, + {":scheme", "https"}, + {"host", "banana:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + SimpleH2Client.send_headers(socket, 1, true, headers) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Path contains dot segment" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Path contains dot segment"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns stream error if path has no leading slash", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "GET"}, - {":path", "path_without_leading_slash"}, - {":scheme", "https"}, - {"host", "banana:#{context.port}"} - ] + headers = [ + {":method", "GET"}, + {":path", "path_without_leading_slash"}, + {":scheme", "https"}, + {"host", "banana:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + SimpleH2Client.send_headers(socket, 1, true, headers) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Path does not start with /" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Path does not start with /"}} = + LoggerHelpers.await_log(:error) end end @@ -2984,44 +2939,40 @@ defmodule HTTP2ProtocolTest do assert Jason.decode!(body)["query_string"] == "a=b?c=d" end + @tag :capture_log test "returns stream error if a non-absolute path is send", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) + socket = SimpleH2Client.setup_connection(context) - headers = [ - {":method", "GET"}, - {":path", "/../non_absolute_path"}, - {":scheme", "https"}, - {":authority", "banana:#{context.port}"} - ] + headers = [ + {":method", "GET"}, + {":path", "/../non_absolute_path"}, + {":scheme", "https"}, + {":authority", "banana:#{context.port}"} + ] - SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + SimpleH2Client.send_headers(socket, 1, true, headers) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Path contains dot segment" + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Path contains dot segment"}} = + LoggerHelpers.await_log(:error) end + @tag :capture_log test "returns stream error if path has no leading slash", context do - output = - capture_log(fn -> - socket = SimpleH2Client.setup_connection(context) - - headers = [ - {":method", "GET"}, - {":path", "path_without_leading_slash"}, - {":scheme", "https"}, - {":authority", "banana:#{context.port}"} - ] - - SimpleH2Client.send_headers(socket, 1, true, headers) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) - - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Path does not start with /" + socket = SimpleH2Client.setup_connection(context) + + headers = [ + {":method", "GET"}, + {":path", "path_without_leading_slash"}, + {":scheme", "https"}, + {":authority", "banana:#{context.port}"} + ] + + SimpleH2Client.send_headers(socket, 1, true, headers) + assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} + + assert %{msg: {:string, "** (Bandit.HTTP2.Errors.StreamError) Path does not start with /"}} = + LoggerHelpers.await_log(:error) end end