diff --git a/.github/workflows/autobahn.yml b/.github/workflows/autobahn.yml index 70b7bd90..8ac15638 100644 --- a/.github/workflows/autobahn.yml +++ b/.github/workflows/autobahn.yml @@ -21,7 +21,7 @@ jobs: matrix: elixir: ${{ fromJSON(inputs.elixirs) }} otp: ${{ fromJSON(inputs.erlangs) }} - case: + case: - "1.*,2.*,3.*,4.*,5.*,6.*,7.*,8.*,10.*" - "9.1.*" - "9.2.*" @@ -69,4 +69,4 @@ jobs: run: | mix deps.get - name: Run Autobahn test - run: mix test --only external_conformance test/bandit/websocket/autobahn_test.exs + run: mix test --only slow test/bandit/websocket/autobahn_test.exs diff --git a/.github/workflows/h2spec.yml b/.github/workflows/h2spec.yml index e455cdf7..eb093d96 100644 --- a/.github/workflows/h2spec.yml +++ b/.github/workflows/h2spec.yml @@ -50,4 +50,4 @@ jobs: run: | mix deps.get - name: Run h2spec test - run: mix test --only external_conformance test/bandit/http2/h2spec_test.exs + run: mix test --only slow test/bandit/http2/h2spec_test.exs diff --git a/test/bandit/clock_test.exs b/test/bandit/clock_test.exs index a23e0a79..d384ed42 100644 --- a/test/bandit/clock_test.exs +++ b/test/bandit/clock_test.exs @@ -9,7 +9,7 @@ defmodule ClockTest do warnings = capture_log(fn -> {"date", date} = Bandit.Clock.date_header() - assert TestHelpers.valid_date_header?(date) + assert DateHelpers.valid_date_header?(date) end) assert warnings =~ "Header timestamp couldn't be fetched from ETS cache" diff --git a/test/bandit/http1/request_test.exs b/test/bandit/http1/request_test.exs index 200a1650..eeadab0f 100644 --- a/test/bandit/http1/request_test.exs +++ b/test/bandit/http1/request_test.exs @@ -1,12 +1,9 @@ defmodule HTTP1RequestTest do - # False due to capture log emptiness check - use ExUnit.Case, async: false + use ExUnit.Case, async: true use ServerHelpers use ReqHelpers use Machete - import ExUnit.CaptureLog - require Logger setup :http_server @@ -35,146 +32,138 @@ defmodule HTTP1RequestTest do end end - describe "suppressing protocol error logging" do + describe "protocol error logging" do + @tag :capture_log test "errors are short logged by default", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") - assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) - - assert output =~ "[error] ** (Bandit.HTTPError) Header read HTTP error" + client = SimpleHTTP1Client.tcp_client(context) + Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - # Make sure we don't log a stacktrace - refute output =~ "lib/bandit/pipeline.ex:" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Header read HTTP error: \"GARBAGE\\r\\n\"" end + @tag :capture_log test "errors are verbosely logged if so configured", context do - context = http_server(context, http_options: [log_protocol_errors: :verbose]) - - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") - assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + context = + context + |> http_server(http_options: [log_protocol_errors: :verbose]) + |> Enum.into(context) - assert output =~ "[error] ** (Bandit.HTTPError) Header read HTTP error" + client = SimpleHTTP1Client.tcp_client(context) + Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - # Make sure we log a stacktrace - assert output =~ "lib/bandit/pipeline.ex:" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "** (Bandit.HTTPError) Header read HTTP error: \"GARBAGE\\r\\n\"" + assert msg =~ "lib/bandit/pipeline.ex:" end test "errors are not logged if so configured", context do - context = http_server(context, http_options: [log_protocol_errors: false]) + context = + context + |> http_server(http_options: [log_protocol_errors: false]) + |> Enum.into(context) - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") - assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - assert output == "" + refute_receive {:log, %{level: :error}} end test "client closure protocol errors are not logged by default", context do - context = http_server(context, http_options: [log_protocol_errors: :verbose]) - client = SimpleHTTP1Client.tcp_client(context) + context = + context + |> http_server(http_options: [log_protocol_errors: :verbose]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/sleep_and_send", ["host: localhost"]) - Process.sleep(100) - - output = - capture_log(fn -> - Transport.close(client) - Process.sleep(500) - end) + Process.sleep(20) + Transport.close(client) - assert output == "" + refute_receive {:log, %{level: :error}} end + @tag :capture_log test "client closure protocol errors are short logged if so configured", context do - context = http_server(context, http_options: [log_client_closures: :short]) - client = SimpleHTTP1Client.tcp_client(context) + context = + context + |> http_server(http_options: [log_client_closures: :short]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/sleep_and_send", ["host: localhost"]) - Process.sleep(100) - - output = - capture_log(fn -> - Transport.close(client) - Process.sleep(500) - end) - - assert output =~ "[error] ** (Bandit.TransportError) Unrecoverable error: closed" + Process.sleep(20) + Transport.close(client) - # Make sure we don't log a stacktrace - refute output =~ "lib/bandit/pipeline.ex:" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.TransportError) Unrecoverable error: closed" end + @tag :capture_log test "client closure protocol errors are verbosely logged if so configured", context do - context = http_server(context, http_options: [log_client_closures: :verbose]) - client = SimpleHTTP1Client.tcp_client(context) + context = + context + |> http_server(http_options: [log_client_closures: :verbose]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/sleep_and_send", ["host: localhost"]) - Process.sleep(100) + Process.sleep(20) + Transport.close(client) + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "** (Bandit.TransportError) Unrecoverable error: closed" + assert msg =~ "lib/bandit/pipeline.ex:" + end - output = - capture_log(fn -> - Transport.close(client) - Process.sleep(500) - end) + @tag :capture_log + test "it should provide useful metadata to logger handler", context do + client = SimpleHTTP1Client.tcp_client(context) + Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - assert output =~ "[error] ** (Bandit.TransportError) Unrecoverable error: closed" + assert_receive {:log, log_event}, 500 - # Make sure we log a stacktrace - assert output =~ "lib/bandit/pipeline.ex:" + assert %{ + meta: %{ + domain: [:elixir, :bandit], + crash_reason: + {%Bandit.HTTPError{message: "Header read HTTP error: \"GARBAGE\\r\\n\""}, + [_ | _] = _stacktrace}, + plug: {__MODULE__, []} + } + } = log_event end end describe "plug error logging" do - 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) + @tag :capture_log + test "it should return 500 and log verbosely when unknown exceptions are raised", context do + {:ok, response} = Req.get(context.req, url: "/unknown_crasher") + assert response.status == 500 - assert output =~ "(RuntimeError) boom" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "(RuntimeError) boom" + assert msg =~ "lib/bandit/pipeline.ex:" end - @tag capture_log: true + @tag :capture_log test "it should provide useful metadata to logger handlers when unknown exceptions are raised", context do - defmodule TestLoggerHandler do - def log(log_event, %{config: %{test_pid: test_pid}}) do - send(test_pid, {:log_event, log_event}) - end - end - - :logger.add_handler( - TestLoggerHandler, - TestLoggerHandler, - %{level: :error, config: %{test_pid: self()}} - ) - {:ok, response} = Req.get(context.req, url: "/unknown_crasher") assert response.status == 500 - assert_receive {:log_event, log_event} + assert_receive {:log, log_event}, 500 assert %{ - level: :error, - msg: _msg, meta: %{ + domain: [:elixir, :bandit], crash_reason: {%RuntimeError{message: "boom"}, [_ | _] = _stacktrace}, - conn: %Plug.Conn{} + conn: %Plug.Conn{}, + plug: {__MODULE__, []} } } = log_event end @@ -183,31 +172,27 @@ defmodule HTTP1RequestTest do raise "boom" end + @tag :capture_log 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_receive {:log, _} end - test "it should log known exceptions if so configured", context do + @tag :capture_log + test "it should verbosely log known exceptions if so configured", context do context = context |> http_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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "(SafeError) boom" + assert msg =~ "lib/bandit/pipeline.ex:" end def known_crasher(_conn) do @@ -227,47 +212,43 @@ defmodule HTTP1RequestTest do end end + @tag :capture_log test "it should unwrap Plug.Conn.WrapperErrors and handle the inner error", context do context = context |> http_server(plug: Router) |> Enum.into(context) - output = - capture_log(fn -> - {:ok, response} = Req.get(context.req, url: "/", base_url: context.base) - assert response.status == 500 - Process.sleep(100) - end) + LoggerHelpers.receive_all_log_events(Router) - refute output =~ "(Plug.Conn.WrapperError)" - assert output =~ "[error] ** (RuntimeError) boom" + {:ok, response} = Req.get(context.req, url: "/", base_url: context.base) + assert response.status == 500 + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + refute msg =~ "(Plug.Conn.WrapperError)" + assert msg =~ "** (RuntimeError) boom" end end describe "invalid requests" do + @tag :capture_log test "returns a 400 if the request cannot be parsed", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") - assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - assert output =~ "Header read HTTP error: \"GARBAGE\\r\\n\"" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Header read HTTP error: \"GARBAGE\\r\\n\"" end + @tag :capture_log test "returns a 400 if the request has an invalid http version", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send(client, "GET", "/echo_components", ["host: localhost"], "0.9") - assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + SimpleHTTP1Client.send(client, "GET", "/echo_components", ["host: localhost"], "0.9") + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) Invalid HTTP version: {0, 9}" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Invalid HTTP version: {0, 9}" end end @@ -312,7 +293,11 @@ defmodule HTTP1RequestTest do end test "closes connection after max_requests is reached", context do - context = http_server(context, http_1_options: [max_requests: 3]) + context = + context + |> http_server(http_1_options: [max_requests: 3]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/echo_components", ["host: banana"]) @@ -337,10 +322,15 @@ defmodule HTTP1RequestTest do end test "idle keepalive connections are closed after read_timeout", context do + context = + context + |> http_server(thousand_island_options: [read_timeout: 100]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/echo_components", ["host: localhost"]) assert {:ok, "200 OK", _headers, _body} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(1100) + Process.sleep(110) assert SimpleHTTP1Client.connection_closed_for_reading?(client) end @@ -454,7 +444,11 @@ defmodule HTTP1RequestTest do end test "gc_every_n_keepalive_requests is respected", context do - context = http_server(context, http_1_options: [gc_every_n_keepalive_requests: 3]) + context = + context + |> http_server(http_1_options: [gc_every_n_keepalive_requests: 3]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/do_gc", ["host: localhost"]) @@ -502,16 +496,14 @@ defmodule HTTP1RequestTest do assert Jason.decode!(body)["host"] == "banana" end + @tag :capture_log test "returns 400 if no host header set in HTTP/1.1", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send(client, "GET", "/echo_components") - assert {:ok, "400 Bad Request", _headers, _body} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + SimpleHTTP1Client.send(client, "GET", "/echo_components") + assert {:ok, "400 Bad Request", _headers, _body} = SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) Unable to obtain host and port: No host header" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Unable to obtain host and port: No host header" end test "sets a blank host if no host header set in HTTP/1.0", context do @@ -547,16 +539,14 @@ defmodule HTTP1RequestTest do assert Jason.decode!(body)["port"] == 1234 end + @tag :capture_log test "returns 400 if port cannot be parsed from host header", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send(client, "GET", "/echo_components", ["host: banana:-1234"]) - assert {:ok, "400 Bad Request", _headers, _body} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + SimpleHTTP1Client.send(client, "GET", "/echo_components", ["host: banana:-1234"]) + assert {:ok, "400 Bad Request", _headers, _body} = SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) Header contains invalid port" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Header contains invalid port" end test "derives port from schema default if no port specified in host header", context do @@ -621,28 +611,24 @@ defmodule HTTP1RequestTest do ) end + @tag :capture_log test "returns 400 if a non-absolute path is send", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send(client, "GET", "./../non_absolute_path", ["host: localhost"]) - assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + SimpleHTTP1Client.send(client, "GET", "./../non_absolute_path", ["host: localhost"]) + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) Unsupported request target (RFC9112§3.2)" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Unsupported request target (RFC9112§3.2)" end + @tag :capture_log test "returns 400 if path has no leading slash", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send(client, "GET", "path_without_leading_slash", ["host: localhost"]) - assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + SimpleHTTP1Client.send(client, "GET", "path_without_leading_slash", ["host: localhost"]) + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) Unsupported request target (RFC9112§3.2)" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Unsupported request target (RFC9112§3.2)" end end @@ -756,16 +742,14 @@ defmodule HTTP1RequestTest do end describe "authority-form request target (RFC9112§3.2.3)" do + @tag :capture_log test "returns 400 for authority-form / CONNECT requests", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send(client, "CONNECT", "www.example.com:80", ["host: localhost"]) - assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + SimpleHTTP1Client.send(client, "CONNECT", "www.example.com:80", ["host: localhost"]) + assert {:ok, "400 Bad Request", _headers, <<>>} = SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) schemeURI is not supported" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) schemeURI is not supported" end end @@ -783,21 +767,22 @@ defmodule HTTP1RequestTest do end describe "request line limits" do + @tag :capture_log test "returns 414 for request lines that are too long", context do - output = - capture_log(fn -> - context = http_server(context, http_1_options: [max_request_line_length: 5000]) - client = SimpleHTTP1Client.tcp_client(context) + context = + context + |> http_server(http_1_options: [max_request_line_length: 5000]) + |> Enum.into(context) - SimpleHTTP1Client.send(client, "GET", String.duplicate("a", 5000 - 14)) + client = SimpleHTTP1Client.tcp_client(context) - assert {:ok, "414 Request-URI Too Long", _headers, <<>>} = - SimpleHTTP1Client.recv_reply(client) + SimpleHTTP1Client.send(client, "GET", String.duplicate("a", 5000 - 14)) - Process.sleep(100) - end) + assert {:ok, "414 Request-URI Too Long", _headers, <<>>} = + SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) Request URI is too long" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Request URI is too long" end end @@ -824,48 +809,50 @@ defmodule HTTP1RequestTest do send_resp(conn, 200, ["O", "K"]) end + @tag :capture_log test "returns 431 for header lines that are too long", context do - output = - capture_log(fn -> - context = http_server(context, http_1_options: [max_header_length: 5000]) - client = SimpleHTTP1Client.tcp_client(context) + context = + context + |> http_server(http_1_options: [max_header_length: 5000]) + |> Enum.into(context) - SimpleHTTP1Client.send(client, "GET", "/echo_components", [ - "host: localhost", - "foo: " <> String.duplicate("a", 5000 - 6) - ]) + client = SimpleHTTP1Client.tcp_client(context) - assert {:ok, "431 Request Header Fields Too Large", _headers, <<>>} = - SimpleHTTP1Client.recv_reply(client) + SimpleHTTP1Client.send(client, "GET", "/echo_components", [ + "host: localhost", + "foo: " <> String.duplicate("a", 5000 - 6) + ]) - Process.sleep(100) - end) + assert {:ok, "431 Request Header Fields Too Large", _headers, <<>>} = + SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) Header too long" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Header too long" end + @tag :capture_log test "returns 431 for too many header lines", context do - output = - capture_log(fn -> - context = http_server(context, http_1_options: [max_header_count: 40]) - client = SimpleHTTP1Client.tcp_client(context) + context = + context + |> http_server(http_1_options: [max_header_count: 40]) + |> Enum.into(context) - headers = for i <- 1..40, do: "header#{i}: foo" + client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send( - client, - "GET", - "/echo_components", - headers ++ ["host: localhost"] - ) + headers = for i <- 1..40, do: "header#{i}: foo" - assert {:ok, "431 Request Header Fields Too Large", _headers, <<>>} = - SimpleHTTP1Client.recv_reply(client) + SimpleHTTP1Client.send( + client, + "GET", + "/echo_components", + headers ++ ["host: localhost"] + ) - Process.sleep(100) - end) + assert {:ok, "431 Request Header Fields Too Large", _headers, <<>>} = + SimpleHTTP1Client.recv_reply(client) - assert output =~ "(Bandit.HTTPError) Too many headers" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Too many headers" end end @@ -919,59 +906,56 @@ defmodule HTTP1RequestTest 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 "rejects a request with non-matching multiple content lengths", context do - output = - capture_log(fn -> - # Use a smaller body size to avoid raciness in reading the response - response = - Req.post!(context.req, - url: "/expect_body_with_multiple_content_length", - headers: [{"content-length", "8000,8001,8000"}], - body: String.duplicate("a", 8_000) - ) + # Use a smaller body size to avoid raciness in reading the response + response = + Req.post!(context.req, + url: "/expect_body_with_multiple_content_length", + headers: [{"content-length", "8000,8001,8000"}], + body: String.duplicate("a", 8_000) + ) + + assert response.status == 400 - assert response.status == 400 - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTPError) Content length unknown error: \"invalid content-length header (RFC9112§6.3.5)\"" + assert msg == + "** (Bandit.HTTPError) Content length unknown error: \"invalid content-length header (RFC9112§6.3.5)\"" end + @tag :capture_log test "rejects a request with negative content-length", context do - output = - capture_log(fn -> - response = - Req.post!(context.req, - url: "/negative_content_length", - headers: [{"content-length", "-321"}], - body: String.duplicate("a", 1_000) - ) + response = + Req.post!(context.req, + url: "/negative_content_length", + headers: [{"content-length", "-321"}], + body: String.duplicate("a", 1_000) + ) - assert response.status == 400 - Process.sleep(100) - end) + assert response.status == 400 - assert output =~ - "(Bandit.HTTPError) Content length unknown error: \"invalid content-length header (RFC9112§6.3.5)\"" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg == + "** (Bandit.HTTPError) Content length unknown error: \"invalid content-length header (RFC9112§6.3.5)\"" end + @tag :capture_log test "rejects a request with non-integer content length", context do - output = - capture_log(fn -> - response = - Req.post!(context.req, - url: "/expect_body_with_multiple_content_length", - headers: [{"content-length", "foo"}], - body: String.duplicate("a", 8_000) - ) + response = + Req.post!(context.req, + url: "/expect_body_with_multiple_content_length", + headers: [{"content-length", "foo"}], + body: String.duplicate("a", 8_000) + ) + + assert response.status == 400 - assert response.status == 400 - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTPError) Content length unknown error: \"invalid content-length header (RFC9112§6.3.5)\"" + assert msg == + "** (Bandit.HTTPError) Content length unknown error: \"invalid content-length header (RFC9112§6.3.5)\"" end test "handles the case where we ask for less than is already in the buffer", context do @@ -999,7 +983,7 @@ defmodule HTTP1RequestTest do "POST /beyond_buffer_read HTTP/1.1\r\nhost: localhost\r\ncontent-length: 5\r\n\r\nAB" ) - Process.sleep(100) + Process.sleep(10) Transport.send(client, "CDE") assert {:ok, "200 OK", _, "ABC,D,E"} = SimpleHTTP1Client.recv_reply(client) @@ -1021,7 +1005,7 @@ defmodule HTTP1RequestTest do "POST /read_one_byte_at_a_time HTTP/1.1\r\nhost: localhost\r\ncontent-length: 5\r\n\r\n" ) - Process.sleep(100) + Process.sleep(10) Transport.send(client, "ABCDE") assert {:ok, "200 OK", _, "ABCDE"} = SimpleHTTP1Client.recv_reply(client) @@ -1032,22 +1016,25 @@ defmodule HTTP1RequestTest do send_resp(conn, 200, body) end + @tag :capture_log test "handles the case where the declared content length is longer than what is sent", context do + context = + context + |> http_server(thousand_island_options: [read_timeout: 100]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) - errors = - capture_log(fn -> - Transport.send( - client, - "POST /short_body HTTP/1.1\r\nhost: localhost\r\ncontent-length: 5\r\n\r\nABC" - ) + Transport.send( + client, + "POST /short_body HTTP/1.1\r\nhost: localhost\r\ncontent-length: 5\r\n\r\nABC" + ) - assert {:ok, "408 Request Timeout", _, ""} = SimpleHTTP1Client.recv_reply(client) - Process.sleep(1100) - end) + assert {:ok, "408 Request Timeout", _, ""} = SimpleHTTP1Client.recv_reply(client) - assert errors =~ "[error] ** (Bandit.HTTPError) Body read timeout" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Body read timeout" end def short_body(conn) do @@ -1090,18 +1077,14 @@ defmodule HTTP1RequestTest do end describe "upgrade handling" do + @tag :capture_log test "raises an ArgumentError on unsupported upgrades", context do - errors = - capture_log(fn -> - response = Req.get!(context.req, url: "/upgrade_unsupported") - - assert response.status == 500 + response = Req.get!(context.req, url: "/upgrade_unsupported") - Process.sleep(100) - end) + assert response.status == 500 - assert errors =~ - "[error] ** (ArgumentError) upgrade to unsupported not supported by Bandit.Adapter" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "** (ArgumentError) upgrade to unsupported not supported by Bandit.Adapter" end def upgrade_unsupported(conn) do @@ -1110,140 +1093,137 @@ defmodule HTTP1RequestTest do |> send_resp(200, "Not supported") end + @tag :capture_log test "returns a 400 and errors loudly in cases where an upgrade is indicated but the connection is not a GET", context do - errors = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - - SimpleHTTP1Client.send( - client, - "POST", - "/upgrade_websocket", - [ - "Host: server.example.com", - "Upgrade: WebSocket", - "Connection: Upgrade", - "Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==", - "Sec-WebSocket-Version: 13" - ] - ) - - assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} - Process.sleep(100) - end) - - assert errors =~ "[error] ** (Bandit.HTTPError) HTTP method POST unsupported" + client = SimpleHTTP1Client.tcp_client(context) + + SimpleHTTP1Client.send( + client, + "POST", + "/upgrade_websocket", + [ + "Host: server.example.com", + "Upgrade: WebSocket", + "Connection: Upgrade", + "Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==", + "Sec-WebSocket-Version: 13" + ] + ) + + assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) HTTP method POST unsupported" end + @tag :capture_log test "returns a 400 and errors loudly in cases where an upgrade is indicated but upgrade header is incorrect", context do - errors = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - - SimpleHTTP1Client.send( - client, - "GET", - "/upgrade_websocket", - [ - "Host: server.example.com", - "Upgrade: NOPE", - "Connection: Upgrade", - "Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==", - "Sec-WebSocket-Version: 13" - ] - ) - - assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} - Process.sleep(100) - end) - - assert errors =~ - "[error] ** (Bandit.HTTPError) 'upgrade' header must contain 'websocket', got [\"NOPE\"]" + client = SimpleHTTP1Client.tcp_client(context) + + SimpleHTTP1Client.send( + client, + "GET", + "/upgrade_websocket", + [ + "Host: server.example.com", + "Upgrade: NOPE", + "Connection: Upgrade", + "Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==", + "Sec-WebSocket-Version: 13" + ] + ) + + assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg == + "** (Bandit.HTTPError) 'upgrade' header must contain 'websocket', got [\"NOPE\"]" end + @tag :capture_log test "returns a 400 and errors loudly in cases where an upgrade is indicated but connection header is incorrect", context do - errors = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - - SimpleHTTP1Client.send( - client, - "GET", - "/upgrade_websocket", - [ - "Host: server.example.com", - "Upgrade: WebSocket", - "Connection: NOPE", - "Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==", - "Sec-WebSocket-Version: 13" - ] - ) - - assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} - Process.sleep(100) - end) - - assert errors =~ - "[error] ** (Bandit.HTTPError) 'connection' header must contain 'upgrade', got [\"NOPE\"]" + client = SimpleHTTP1Client.tcp_client(context) + + SimpleHTTP1Client.send( + client, + "GET", + "/upgrade_websocket", + [ + "Host: server.example.com", + "Upgrade: WebSocket", + "Connection: NOPE", + "Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==", + "Sec-WebSocket-Version: 13" + ] + ) + + assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg == + "** (Bandit.HTTPError) 'connection' header must contain 'upgrade', got [\"NOPE\"]" end + @tag :capture_log test "returns a 400 and errors loudly in cases where an upgrade is indicated but key header is incorrect", context do - errors = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) + client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send( - client, - "GET", - "/upgrade_websocket", - [ - "Host: server.example.com", - "Upgrade: WebSocket", - "Connection: Upgrade", - "Sec-WebSocket-Version: 13" - ] - ) + SimpleHTTP1Client.send( + client, + "GET", + "/upgrade_websocket", + [ + "Host: server.example.com", + "Upgrade: WebSocket", + "Connection: Upgrade", + "Sec-WebSocket-Version: 13" + ] + ) - assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} - Process.sleep(100) - end) + assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} - assert errors =~ "[error] ** (Bandit.HTTPError) 'sec-websocket-key' header is absent" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) 'sec-websocket-key' header is absent" end + @tag :capture_log test "returns a 400 and errors loudly in cases where an upgrade is indicated but version header is incorrect", context do - errors = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - - SimpleHTTP1Client.send( - client, - "GET", - "/upgrade_websocket", - [ - "Host: server.example.com", - "Upgrade: WebSocket", - "Connection: Upgrade", - "Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==", - "Sec-WebSocket-Version: 99" - ] - ) - - assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} - Process.sleep(100) - end) - - assert errors =~ - "[error] ** (Bandit.HTTPError) 'sec-websocket-version' header must equal '13', got [\"99\"]" + client = SimpleHTTP1Client.tcp_client(context) + + SimpleHTTP1Client.send( + client, + "GET", + "/upgrade_websocket", + [ + "Host: server.example.com", + "Upgrade: WebSocket", + "Connection: Upgrade", + "Sec-WebSocket-Key: dGhlIHNhbXBsZSBub25jZQ==", + "Sec-WebSocket-Version: 99" + ] + ) + + assert SimpleHTTP1Client.recv_reply(client) ~> {:ok, "400 Bad Request", list(), ""} + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg == + "** (Bandit.HTTPError) 'sec-websocket-version' header must equal '13', got [\"99\"]" end test "returns a 400 and errors loudly if websocket support is not enabled", context do - context = http_server(context, websocket_options: [enabled: false]) + context = + context + |> http_server(websocket_options: [enabled: false]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send( @@ -1293,7 +1273,7 @@ defmodule HTTP1RequestTest do assert response.status == 200 [date] = response.headers["date"] - assert TestHelpers.valid_date_header?(date) + assert DateHelpers.valid_date_header?(date) end test "returns user-defined date header instead of internal version", context do @@ -1532,7 +1512,8 @@ defmodule HTTP1RequestTest do test "falls back to no encoding if compression is disabled", context do context = - http_server(context, http_options: [compress: false]) + context + |> http_server(http_options: [compress: false]) |> Enum.into(context) response = @@ -1914,7 +1895,7 @@ defmodule HTTP1RequestTest do client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/send_inform", ["host: localhost"]) - Process.sleep(100) + Process.sleep(10) assert {:ok, "100 Continue", headers, rest} = SimpleHTTP1Client.recv_reply(client) assert Bandit.Headers.get_header(headers, :"x-from") == "inform" assert {:ok, "200 OK", _headers, "Informer"} = SimpleHTTP1Client.parse_response(client, rest) @@ -1958,63 +1939,55 @@ defmodule HTTP1RequestTest do end describe "abnormal handler processes" do + @tag :capture_log test "returns a 500 if the plug raises an exception", context do - output = - capture_log(fn -> - response = Req.get!(context.req, url: "/raise_error") - assert response.status == 500 - Process.sleep(100) - end) + response = Req.get!(context.req, url: "/raise_error") + assert response.status == 500 - assert output =~ "(RuntimeError) boom" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "(RuntimeError) boom" end def raise_error(_conn) do raise "boom" end + @tag :capture_log test "returns a 500 if the plug throws", context do - output = - capture_log(fn -> - response = Req.get!(context.req, url: "/throws") - assert response.status == 500 - Process.sleep(100) - end) + response = Req.get!(context.req, url: "/throws") + assert response.status == 500 - assert output =~ "(throw) \"something\"" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "(throw) \"something\"" end def throws(_conn) do throw("something") end + @tag :capture_log test "returns a 500 if the plug exits", context do - output = - capture_log(fn -> - response = Req.get!(context.req, url: "/exits") - assert response.status == 500 - Process.sleep(100) - end) + response = Req.get!(context.req, url: "/exits") + assert response.status == 500 - assert output =~ "(exit) \"something\"" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "(exit) \"something\"" end def exits(_conn) do exit("something") end + @tag :capture_log test "does not send an error response if the plug has already sent one before raising", context do - output = - capture_log(fn -> - client = SimpleHTTP1Client.tcp_client(context) - SimpleHTTP1Client.send(client, "GET", "/send_and_raise_error", ["host: banana"]) - assert {:ok, "200 OK", _headers, _} = SimpleHTTP1Client.recv_reply(client) - assert SimpleHTTP1Client.connection_closed_for_reading?(client) - Process.sleep(100) - end) + client = SimpleHTTP1Client.tcp_client(context) + SimpleHTTP1Client.send(client, "GET", "/send_and_raise_error", ["host: banana"]) + assert {:ok, "200 OK", _headers, _} = SimpleHTTP1Client.recv_reply(client) + assert SimpleHTTP1Client.connection_closed_for_reading?(client) - assert output =~ "(RuntimeError) boom" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "(RuntimeError) boom" end def send_and_raise_error(conn) do @@ -2022,15 +1995,14 @@ defmodule HTTP1RequestTest do raise "boom" end + @tag :capture_log test "returns a 500 if the plug does not return anything", context do - output = - capture_log(fn -> - response = Req.get!(context.req, url: "/noop") - assert response.status == 500 - Process.sleep(100) - end) - - assert output =~ + response = Req.get!(context.req, url: "/noop") + assert response.status == 500 + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg =~ "(Plug.Conn.NotSentError) a response was neither set nor sent from the connection" end @@ -2038,16 +2010,15 @@ defmodule HTTP1RequestTest do conn end + @tag :capture_log test "returns a 500 if the plug does not return a conn", context do - output = - capture_log(fn -> - response = Req.get!(context.req, url: "/return_garbage") + response = Req.get!(context.req, url: "/return_garbage") + + assert response.status == 500 - assert response.status == 500 - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ + assert msg =~ "(RuntimeError) Expected Elixir.HTTP1RequestTest.call/2 to return %Plug.Conn{} but got: :nope" end @@ -2055,133 +2026,104 @@ defmodule HTTP1RequestTest do :nope 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) + test "survives EXIT messages from normally terminating spawned processes", context do + 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 GenServer call & will complete before the handler process handles - # the handle_info call returned by the spawned process. Look at the logged - # errors instead - assert errors == "" + refute_receive {:log, _} end def spawn_child(conn) do spawn_link(fn -> exit(:normal) end) + Process.sleep(10) send_resp(conn, 204, "") end - end - - test "does not do anything special with EXIT messages from abnormally terminating spawned processes", - context do - context = http_server(context, http_1_options: [log_unknown_messages: true]) - errors = - capture_log(fn -> - Req.get!(url: "/spawn_abnormal_child", base_url: context[:base]) - - # Let the backing process see & handle the handle_info EXIT message - Process.sleep(100) - end) + @tag :capture_log + test "survives EXIT messages from abnormally terminating spawned processes", context do + response = Req.get!(context.req, url: "/spawn_abnormal_child") + assert response.status == 204 - # The return value here isn't relevant, since the HTTP call is done within - # a single GenServer call & will complete before the handler process handles - # the handle_info call returned by the spawned process. Look at the logged - # errors instead - assert errors =~ ~r[received unexpected message in handle_info/2] - end + refute_receive {:log, _} + end - def spawn_abnormal_child(conn) do - spawn_link(fn -> exit(:abnormal) end) - send_resp(conn, 204, "") + def spawn_abnormal_child(conn) do + spawn_link(fn -> exit(:abnormal) end) + Process.sleep(10) + send_resp(conn, 204, "") + end end describe "telemetry" do test "it should send `start` events for normally completing requests", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :start]]}) - Req.get!(context.req, url: "/send_200") - Process.sleep(100) + assert_receive {:telemetry, [:bandit, :request, :start], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer() + } - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :start], %{monotonic_time: integer()}, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should send `stop` events for normally completing requests", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) + Req.get!(context.req, url: "/send_200") - # Use a manually built request so we can count exact bytes - request = "GET /send_200 HTTP/1.1\r\nhost: localhost\r\n\r\n" - client = SimpleHTTP1Client.tcp_client(context) - Transport.send(client, request) - Process.sleep(100) + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + resp_body_bytes: 0, + resp_start_time: integer(), + resp_end_time: integer() + } - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - resp_body_bytes: 0, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add req metrics to `stop` events for requests with no request body", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.post!(context.req, url: "/do_read_body", body: <<>>) - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - req_body_start_time: integer(), - req_body_end_time: integer(), - req_body_bytes: 0, - resp_body_bytes: 2, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + req_body_start_time: integer(), + req_body_end_time: integer(), + req_body_bytes: 0, + resp_body_bytes: 2, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end def do_read_body(conn) do @@ -2190,274 +2132,219 @@ defmodule HTTP1RequestTest do end test "it should add req metrics to `stop` events for requests with request body", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.post!(context.req, url: "/do_read_body", body: String.duplicate("a", 80)) - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - req_body_start_time: integer(), - req_body_end_time: integer(), - req_body_bytes: 80, - resp_body_bytes: 2, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + req_body_start_time: integer(), + req_body_end_time: integer(), + req_body_bytes: 80, + resp_body_bytes: 2, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add req metrics to `stop` events for chunked request body", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - stream = Stream.repeatedly(fn -> "a" end) |> Stream.take(80) Req.post!(context.req, url: "/do_read_body", body: stream) - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - req_body_start_time: integer(), - req_body_end_time: integer(), - req_body_bytes: 80, - resp_body_bytes: 2, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + req_body_start_time: integer(), + req_body_end_time: integer(), + req_body_bytes: 80, + resp_body_bytes: 2, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add req metrics to `stop` events for requests with content encoding", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.post!(context.req, url: "/do_read_body", body: String.duplicate("a", 80), headers: [{"accept-encoding", "gzip"}] ) - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - req_body_start_time: integer(), - req_body_end_time: integer(), - req_body_bytes: 80, - resp_uncompressed_body_bytes: 2, - resp_body_bytes: 22, - resp_compression_method: "gzip", - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + req_body_start_time: integer(), + req_body_end_time: integer(), + req_body_bytes: 80, + resp_uncompressed_body_bytes: 2, + resp_body_bytes: 22, + resp_compression_method: "gzip", + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add (some) resp metrics to `stop` events for chunked responses", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.get!(context.req, url: "/send_chunked_200") - Process.sleep(100) + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + resp_body_bytes: 2, + resp_start_time: integer(), + resp_end_time: integer() + } - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - resp_body_bytes: 2, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add resp metrics to `stop` events for sendfile responses", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.get!(context.req, url: "/send_full_file") - Process.sleep(100) + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - resp_body_bytes: 6, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + resp_body_bytes: 6, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end + @tag :capture_log test "it should send `stop` events for malformed requests", context do - output = - capture_log(fn -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - - client = SimpleHTTP1Client.tcp_client(context) - Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], %{monotonic_time: integer(), duration: integer()}, - %{ - plug: {__MODULE__, []}, - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - error: string() - }} - ] - end) - - assert output =~ "(Bandit.HTTPError) Header read HTTP error: \"GARBAGE\\r\\n\"" + client = SimpleHTTP1Client.tcp_client(context) + Transport.send(client, "GET / HTTP/1.1\r\nGARBAGE\r\n\r\n") + + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{monotonic_time: integer(), duration: integer()} + + assert metadata + ~> %{ + plug: {__MODULE__, []}, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + error: string() + } end + @tag :capture_log test "it should send `stop` events for timed out requests", context do - output = - capture_log(fn -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - - client = SimpleHTTP1Client.tcp_client(context) - Transport.send(client, "GET / HTTP/1.1\r\nfoo: bar\r\n") - Process.sleep(1100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], %{monotonic_time: integer(), duration: integer()}, - %{ - plug: {__MODULE__, []}, - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - error: "Header read timeout" - }} - ] - end) - - assert output =~ "(Bandit.HTTPError) Header read timeout" + client = SimpleHTTP1Client.tcp_client(context) + Transport.send(client, "GET / HTTP/1.1\r\nfoo: bar\r\n") + + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{monotonic_time: integer(), duration: integer()} + + assert( + metadata + ~> %{ + plug: {__MODULE__, []}, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + error: "Header read timeout" + } + ) end + @tag :capture_log test "it should send `exception` events for raising requests", context do - output = - capture_log(fn -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]}) - - Req.get!(context.req, url: "/raise_error") + Req.get!(context.req, url: "/raise_error") - Process.sleep(100) + assert_receive {:telemetry, [:bandit, :request, :exception], measurements, metadata}, 500 - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[: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 measurements + ~> %{monotonic_time: integer()} - assert output =~ "(RuntimeError) boom" + assert metadata + ~> %{ + 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 + @tag :capture_log test "it should not send `exception` events for throwing requests", context do - output = - capture_log(fn -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]}) - - Req.get!(context.req, url: "/uncaught_throw") - - Process.sleep(100) - - assert [] = Bandit.TelemetryCollector.get_events(collector_pid) - end) + Req.get!(context.req, url: "/uncaught_throw") - assert output =~ "(throw) \"thrown\"" + refute_receive {:telemetry, [:bandit, :request, :stop], _, _} 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 -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]}) + Req.get!(context.req, url: "/uncaught_exit") - Req.get!(context.req, url: "/uncaught_exit") - - Process.sleep(100) - - assert [] = Bandit.TelemetryCollector.get_events(collector_pid) - end) - - assert output =~ "(exit) \"exited\"" + refute_receive {:telemetry, [:bandit, :request, :exception], _, _} end def uncaught_exit(_conn) do @@ -2466,16 +2353,30 @@ defmodule HTTP1RequestTest do end describe "connection closure / error handling" do + @tag :capture_log test "raises an error if client closes while headers are being read", context do + context = + context + |> http_server(http_options: [log_client_closures: :short]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) - Transport.send(client, "GET / HTTP/1.1\r\nHost:") + + Transport.send(client, "GET / HTTP/1.1\r\nHost: localhost\r\nFoo: ") + Process.sleep(10) Transport.close(client) - Process.sleep(100) - assert ThousandIsland.connection_pids(context.server_pid) == {:ok, []} + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Header read socket error: :closed" end + @tag :capture_log test "raises an error if client closes while body is being read", context do - context = http_server(context, http_options: [log_client_closures: :verbose]) + context = + context + |> http_server(http_options: [log_client_closures: :short]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "POST", "/expect_incomplete_body", [ @@ -2484,16 +2385,11 @@ defmodule HTTP1RequestTest do ]) Transport.send(client, "ABC") + Process.sleep(10) + Transport.close(client) - output = - capture_log(fn -> - Transport.close(client) - Process.sleep(500) - end) - - assert output =~ "[error] ** (Bandit.TransportError) Unrecoverable error: closed" - refute output =~ "IMPOSSIBLE" - assert ThousandIsland.connection_pids(context[:server_pid]) == {:ok, []} + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.TransportError) Unrecoverable error: closed" end def expect_incomplete_body(conn) do @@ -2501,22 +2397,25 @@ defmodule HTTP1RequestTest do Logger.error("IMPOSSIBLE") end + @tag :capture_log test "raises an error if client closes while body is being written", context do - context = http_server(context, http_options: [log_client_closures: :verbose]) + context = + context + |> http_server(http_options: [log_client_closures: :short]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/sleep_and_send", ["host: localhost"]) - Process.sleep(100) + Process.sleep(10) Transport.close(client) - output = capture_log(fn -> Process.sleep(500) end) - assert output =~ "[error] ** (Bandit.TransportError) Unrecoverable error: closed" - refute output =~ "IMPOSSIBLE" - assert ThousandIsland.connection_pids(context[:server_pid]) == {:ok, []} + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.TransportError) Unrecoverable error: closed" end def sleep_and_send(conn) do - Process.sleep(200) + Process.sleep(100) conn = send_resp(conn, 200, "IMPOSSIBLE") @@ -2525,46 +2424,45 @@ defmodule HTTP1RequestTest do end test "returns an error if client closes while chunked body is being written", context do - context = http_server(context, http_options: [log_client_closures: :verbose]) + context = + context + |> http_server(http_options: [log_client_closures: :verbose]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/sleep_and_send_chunked", ["host: localhost"]) - Process.sleep(100) + Process.sleep(20) Transport.close(client) - - output = capture_log(fn -> Process.sleep(500) end) - assert output == "" - assert ThousandIsland.connection_pids(context[:server_pid]) == {:ok, []} end def sleep_and_send_chunked(conn) do conn = send_chunked(conn, 200) - - Process.sleep(200) + Process.sleep(100) assert chunk(conn, "IMPOSSIBLE") == {:error, :closed} - conn end + @tag :capture_log test "raises an error if client closes before sendfile body is being written", context do - context = http_server(context, http_options: [log_client_closures: :verbose]) + context = + context + |> http_server(http_options: [log_client_closures: :short]) + |> Enum.into(context) + client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/sleep_and_sendfile", ["host: localhost"]) - Process.sleep(100) + Process.sleep(10) Transport.close(client) - output = capture_log(fn -> Process.sleep(500) end) - assert output =~ "[error] ** (Bandit.TransportError) Unrecoverable error: closed" - refute output =~ "IMPOSSIBLE" - assert ThousandIsland.connection_pids(context[:server_pid]) == {:ok, []} + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.TransportError) Unrecoverable error: closed" end def sleep_and_sendfile(conn) do - Process.sleep(200) - + Process.sleep(100) conn = send_file(conn, 204, Path.join([__DIR__, "../../support/sendfile"]), 0, :all) - Logger.error("IMPOSSIBLE") conn end @@ -2573,12 +2471,10 @@ defmodule HTTP1RequestTest do client = SimpleHTTP1Client.tcp_client(context) SimpleHTTP1Client.send(client, "GET", "/hello_world", ["host: localhost"]) - Process.sleep(100) SimpleHTTP1Client.recv_reply(client) Transport.close(client) - Process.sleep(500) - assert ThousandIsland.connection_pids(context.server_pid) == {:ok, []} + refute_receive {:log, _} end end end diff --git a/test/bandit/http2/h2spec_test.exs b/test/bandit/http2/h2spec_test.exs index 8dc94011..329767f7 100644 --- a/test/bandit/http2/h2spec_test.exs +++ b/test/bandit/http2/h2spec_test.exs @@ -2,7 +2,7 @@ defmodule H2SpecTest do use ExUnit.Case, async: true use ServerHelpers - @moduletag :external_conformance + @moduletag :slow @moduletag timeout: 600_000 setup :https_server @@ -11,7 +11,7 @@ defmodule H2SpecTest do conn |> send_resp(200, "OK") end - @tag capture_log: true + @tag :capture_log test "passes h2spec", context do {cmd, opts} = case System.find_executable("h2spec") do diff --git a/test/bandit/http2/plug_test.exs b/test/bandit/http2/plug_test.exs index 872a132b..f78bd41e 100644 --- a/test/bandit/http2/plug_test.exs +++ b/test/bandit/http2/plug_test.exs @@ -1,12 +1,9 @@ defmodule HTTP2PlugTest do - # False due to capture log emptiness check - use ExUnit.Case, async: false + use ExUnit.Case, async: true use ServerHelpers use ReqHelpers use Machete - import ExUnit.CaptureLog - setup :https_server setup :req_h2_client @@ -34,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) - - assert output =~ "(RuntimeError) boom" + {:ok, response} = Req.get(context.req, url: "/unknown_crasher") + assert response.status == 500 + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "** (RuntimeError) boom" end def unknown_crasher(_conn) do @@ -50,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) - - assert output == "" + {:ok, response} = Req.get(context.req, url: "/known_crasher") + assert response.status == 418 + + refute_receive {:log, %{level: :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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "** (SafeError) boom" end def known_crasher(_conn) do @@ -143,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") @@ -150,17 +140,21 @@ defmodule HTTP2PlugTest do end def other_process_body_read(conn) do - Task.async(fn -> - assert_raise(RuntimeError, "Adapter functions must be called by stream owner", fn -> - read_body(conn) + {:ok, "OK", conn} = read_body(conn) + + error = + Task.async(fn -> + try do + read_body(conn) + rescue + error -> error + end end) + |> Task.await() - :ok - end) - |> Task.await() - |> case do - :ok -> send_resp(conn, 200, "OK") - end + assert error == %RuntimeError{message: "Adapter functions must be called by stream owner"} + + send_resp(conn, 200, "OK") end test "reading request body respects length option", context do @@ -195,15 +189,17 @@ defmodule HTTP2PlugTest do SimpleH2Client.send_body(socket, 1, false, "A") {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) {:ok, 1, _} = SimpleH2Client.recv_window_update(socket) - Process.sleep(500) + Process.sleep(50) SimpleH2Client.send_body(socket, 1, true, "BC") assert SimpleH2Client.successful_response?(socket, 1, false) assert SimpleH2Client.recv_body(socket) == {:ok, 1, true, ""} + + Process.sleep(100) end def timeout_body_read(conn) do - {:more, body, conn} = read_body(conn, read_timeout: 100) + {:more, body, conn} = read_body(conn, read_timeout: 10) assert body == "A" {:ok, body, conn} = read_body(conn) assert body == "BC" @@ -224,17 +220,21 @@ defmodule HTTP2PlugTest do SimpleH2Client.send_headers(socket, 1, false, headers) SimpleH2Client.send_body(socket, 1, true, "ABC") - {:ok, 0, _} = SimpleH2Client.recv_window_update(socket) - - assert SimpleH2Client.successful_response?(socket, 1, false) - assert SimpleH2Client.recv_body(socket) == {:ok, 1, true, ""} - - Process.sleep(1000) + # Ordering of window update frames can be racy due to h2's internal message passing + assert [ + SimpleH2Client.recv_frame(socket), + SimpleH2Client.recv_frame(socket), + SimpleH2Client.recv_frame(socket) + ] + ~> in_any_order([ + {:ok, :window_update, term(), 0, term()}, + {:ok, :headers, term(), 1, term()}, + {:ok, :data, term(), 1, term()} + ]) end def no_body_read(conn) do - Process.sleep(100) - conn |> send_resp(200, <<>>) + conn |> send_resp(200, "") end test "writing response headers", context do @@ -250,7 +250,7 @@ defmodule HTTP2PlugTest do "X-Response-Header" => ["Response"] } = response.headers - assert TestHelpers.valid_date_header?(date) + assert DateHelpers.valid_date_header?(date) end def header_write_test(conn) do @@ -360,24 +360,27 @@ 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") + response = Req.get!(context.req, url: "/other_process_send_body") assert response.status == 200 end def other_process_send_body(conn) do - Task.async(fn -> - assert_raise(RuntimeError, "Adapter functions must be called by stream owner", fn -> - conn |> send_resp(200, "NOT OK") + error = + Task.async(fn -> + try do + send_resp(conn, 200, "NOT OK") + rescue + error -> error + end end) + |> Task.await() - :ok - end) - |> Task.await() - |> case do - :ok -> send_resp(conn, 200, "OK") - end + assert error == %RuntimeError{message: "Adapter functions must be called by stream owner"} + + send_resp(conn, 200, "OK") end test "sending a chunk", context do @@ -396,28 +399,32 @@ 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") + response = Req.get!(context.req, url: "/other_process_set_chunk") assert response.status == 200 end def other_process_set_chunk(conn) do - Task.async(fn -> - assert_raise(RuntimeError, "Adapter functions must be called by stream owner", fn -> - conn |> send_chunked(200) + error = + Task.async(fn -> + try do + send_chunked(conn, 200) + rescue + error -> error + end end) + |> Task.await() - :ok - end) - |> Task.await() - |> case do - :ok -> send_resp(conn, 200, "OK") - end + assert error == %RuntimeError{message: "Adapter functions must be called by stream owner"} + + send_resp(conn, 200, "OK") 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") + response = Req.get!(context.req, url: "/other_process_send_chunk") assert response.status == 200 end @@ -425,31 +432,30 @@ defmodule HTTP2PlugTest do def other_process_send_chunk(conn) do conn = conn |> send_chunked(200) - Task.async(fn -> - assert_raise(RuntimeError, "Adapter functions must be called by stream owner", fn -> - conn |> chunk("NOT OK") + error = + Task.async(fn -> + try do + chunk(conn, "NOT OK") + rescue + error -> error + end end) + |> Task.await() - :ok - end) - |> Task.await() - |> case do - :ok -> tap(conn, &chunk(&1, "OK")) - end + assert error == %RuntimeError{message: "Adapter functions must be called by stream owner"} + + {:ok, conn} = chunk(conn, "OK") + conn 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 + {:ok, response} = Req.get(context.req, url: "/upgrade_unsupported") + assert response.status == 500 - Process.sleep(100) - end) - - assert errors =~ - "(ArgumentError) upgrade to unsupported not supported by Bandit.Adapter" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "** (ArgumentError) upgrade to unsupported not supported by Bandit.Adapter" end def upgrade_unsupported(conn) do @@ -459,32 +465,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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - 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 @@ -523,16 +525,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 + {:ok, response} = Req.get(context.req, url: "/send_file?offset=1&length=3000") + assert response.status == 500 - Process.sleep(100) - end) - - assert errors =~ "(RuntimeError) Cannot read 3000 bytes starting at 1" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg =~ "** (RuntimeError) Cannot read 3000 bytes starting at 1" end def send_file(conn) do @@ -547,28 +546,35 @@ 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") + response = Req.get!(context.req, url: "/other_process_send_file") assert response.status == 200 end def other_process_send_file(conn) do - Task.async(fn -> - assert_raise(RuntimeError, "Adapter functions must be called by stream owner", fn -> - conn - |> send_file(200, Path.join([__DIR__, "../../support/sendfile"]), 0, :all) + error = + Task.async(fn -> + try do + send_file(conn, 200, Path.join([__DIR__, "../../support/sendfile"]), 0, :all) + rescue + error -> error + end end) + |> Task.await() - :ok - end) - |> Task.await() - |> case do - :ok -> send_resp(conn, 200, "OK") - end + assert error == %RuntimeError{message: "Adapter functions must be called by stream owner"} + + send_resp(conn, 200, "OK") end test "sending a body blocks on connection flow control", context do + context = + context + |> https_server(thousand_island_options: [read_timeout: 500]) + |> Enum.into(context) + socket = SimpleH2Client.setup_connection(context) SimpleH2Client.send_simple_headers(socket, 1, :get, "/blocking_test", context.port) @@ -604,14 +610,19 @@ defmodule HTTP2PlugTest do {:ok, 1, false, timings} = SimpleH2Client.recv_body(socket) [non_blocked, blocked] = Jason.decode!(timings) - # Ensure the the non-blocked chunks (60k worth) were *much* faster than the + # Ensure the non-blocked chunks (60k worth) were *much* faster than the # blocked chunk (which only did 10k) - assert non_blocked < 20 + assert non_blocked < 50 assert blocked > 100 - assert blocked < 300 + assert blocked < 250 end test "sending a body blocks on stream flow control", context do + context = + context + |> https_server(thousand_island_options: [read_timeout: 500]) + |> Enum.into(context) + socket = SimpleH2Client.setup_connection(context) # Give ourselves lots of room on the connection so we can focus on the @@ -649,9 +660,9 @@ defmodule HTTP2PlugTest do # Ensure the the non-blocked chunks (60k worth) were *much* faster than the # blocked chunk (which only did 10k) - assert non_blocked < 10 + assert non_blocked < 50 assert blocked > 100 - assert blocked < 200 + assert blocked < 250 end def blocking_test(conn) do @@ -693,7 +704,7 @@ defmodule HTTP2PlugTest do assert {:ok, 1, false, _, _} = SimpleH2Client.recv_headers(socket, ctx) assert {:ok, 1, true, "Informer"} = SimpleH2Client.recv_body(socket) - assert TestHelpers.valid_date_header?(date) + assert DateHelpers.valid_date_header?(date) assert SimpleH2Client.connection_alive?(socket) end @@ -703,24 +714,27 @@ 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") + response = Req.get!(context.req, url: "/other_process_send_inform") assert response.status == 200 end def other_process_send_inform(conn) do - Task.async(fn -> - assert_raise(RuntimeError, "Adapter functions must be called by stream owner", fn -> - conn |> inform(100, []) + error = + Task.async(fn -> + try do + inform(conn, 100, []) + rescue + error -> error + end end) + |> Task.await() - :ok - end) - |> Task.await() - |> case do - :ok -> send_resp(conn, 200, "OK") - end + assert error == %RuntimeError{message: "Adapter functions must be called by stream owner"} + + send_resp(conn, 200, "OK") end test "reading HTTP version", context do @@ -750,44 +764,33 @@ 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_receive {:log, %{level: :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 describe "telemetry" do test "it should send `start` events for normally completing requests", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :start]]}) - Req.get!(context.req, url: "/send_200") - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :start], %{monotonic_time: integer()}, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :start], measurements, metadata}, 500 + + assert measurements ~> %{monotonic_time: integer()} + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end def send_200(conn) do @@ -795,59 +798,55 @@ defmodule HTTP2PlugTest do end test "it should send `stop` events for normally completing requests", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.get!(context.req, url: "/send_200") - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - resp_body_bytes: 0, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + resp_body_bytes: 0, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add req metrics to `stop` events for requests with no request body", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.post!(context.req, url: "/do_read_body", body: <<>>) - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - req_body_start_time: integer(), - req_body_end_time: integer(), - req_body_bytes: 0, - resp_body_bytes: 2, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + req_body_start_time: integer(), + req_body_end_time: integer(), + req_body_bytes: 0, + resp_body_bytes: 2, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end def do_read_body(conn) do @@ -856,220 +855,178 @@ defmodule HTTP2PlugTest do end test "it should add req metrics to `stop` events for requests with request body", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.post!(context.req, url: "/do_read_body", body: String.duplicate("a", 80)) - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - req_body_start_time: integer(), - req_body_end_time: integer(), - req_body_bytes: 80, - resp_body_bytes: 2, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + req_body_start_time: integer(), + req_body_end_time: integer(), + req_body_bytes: 80, + resp_body_bytes: 2, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add req metrics to `stop` events for requests with content encoding", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.post!(context.req, url: "/do_read_body", body: String.duplicate("a", 80), headers: [{"accept-encoding", "gzip"}] ) - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - req_body_start_time: integer(), - req_body_end_time: integer(), - req_body_bytes: 80, - resp_uncompressed_body_bytes: 2, - resp_body_bytes: 22, - resp_compression_method: "gzip", - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + req_body_start_time: integer(), + req_body_end_time: integer(), + req_body_bytes: 80, + resp_uncompressed_body_bytes: 2, + resp_body_bytes: 22, + resp_compression_method: "gzip", + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add resp metrics to `stop` events for chunked responses", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.get!(context.req, url: "/chunk_test") - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - resp_body_bytes: 4, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + resp_body_bytes: 4, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end test "it should add resp metrics to `stop` events for sendfile responses", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - Req.get!(context.req, url: "/send_full_file") - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer(), - resp_body_bytes: 6, - resp_start_time: integer(), - resp_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer(), + resp_body_bytes: 6, + resp_start_time: integer(), + resp_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end + @tag :capture_log test "it should send `stop` events for malformed requests", context do - output = - capture_log(fn -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - - 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>> - - SimpleH2Client.send_frame(socket, 1, 5, 1, headers) - - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], %{monotonic_time: integer(), duration: integer()}, - %{ - plug: {__MODULE__, []}, - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - error: string() - }} - ] - end) - - assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received uppercase header" + 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>> + + SimpleH2Client.send_frame(socket, 1, 5, 1, headers) + + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements ~> %{monotonic_time: integer(), duration: integer()} + + assert metadata + ~> %{ + 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 -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]}) - - Req.get(context.req, url: "/raise_error") - - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[: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_receive {:telemetry, [:bandit, :request, :exception], measurements, metadata}, 500 + + assert measurements ~> %{monotonic_time: integer()} + + assert metadata + ~> %{ + 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 -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]}) - - Req.get!(context.req, url: "/uncaught_throw") - - Process.sleep(100) - - assert [] = Bandit.TelemetryCollector.get_events(collector_pid) - end) + Req.get!(context.req, url: "/uncaught_throw") - assert output =~ "(throw) \"thrown\"" + refute_receive {:telemetry, [: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 -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]}) - - Req.get!(context.req, url: "/uncaught_exit") - - Process.sleep(100) - - assert [] = Bandit.TelemetryCollector.get_events(collector_pid) - end) + Req.get!(context.req, url: "/uncaught_exit") - assert output =~ "(exit) \"exited\"" + refute_receive {:telemetry, [: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 1588acdf..1b2d426f 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 @@ -20,9 +19,9 @@ defmodule HTTP2ProtocolTest do end) |> Enum.each(fn byte -> Transport.send(socket, byte) end) - assert {:ok, 4, 0, 0, <<>>} == SimpleH2Client.recv_frame(socket) - assert {:ok, 4, 1, 0, <<>>} == SimpleH2Client.recv_frame(socket) - assert {:ok, 6, 1, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>} == SimpleH2Client.recv_frame(socket) + assert {:ok, :settings, 0, 0, <<>>} == SimpleH2Client.recv_frame(socket) + assert {:ok, :settings, 1, 0, <<>>} == SimpleH2Client.recv_frame(socket) + assert {:ok, :ping, 1, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>} == SimpleH2Client.recv_frame(socket) end test "it should handle cases where multiple frames arrive in the same packet", context do @@ -35,15 +34,14 @@ defmodule HTTP2ProtocolTest do <<0, 0, 0, 4, 0, 0, 0, 0, 0>> <> <<0, 0, 8, 6, 0, 0, 0, 0, 0, 1, 2, 3, 4, 5, 6, 7, 8>> ) - assert {:ok, 4, 0, 0, <<>>} == SimpleH2Client.recv_frame(socket) - assert {:ok, 4, 1, 0, <<>>} == SimpleH2Client.recv_frame(socket) - assert {:ok, 6, 1, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>} == SimpleH2Client.recv_frame(socket) + assert {:ok, :settings, 0, 0, <<>>} == SimpleH2Client.recv_frame(socket) + assert {:ok, :settings, 1, 0, <<>>} == SimpleH2Client.recv_frame(socket) + assert {:ok, :ping, 1, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>} == SimpleH2Client.recv_frame(socket) end 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,83 @@ 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_receive {:log, %{level: :warning, msg: {:string, msg}}}, 500 + 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert errors =~ - "(Bandit.HTTP2.Errors.ConnectionError) Invalid SETTINGS frame (RFC9113§6.5)" + assert msg == + "** (Bandit.HTTP2.Errors.ConnectionError) Invalid SETTINGS frame (RFC9113§6.5)" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg == + "** (Bandit.HTTP2.Errors.ConnectionError) Received WINDOW_UPDATE in idle state" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert errors =~ - "[error] ** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" + assert msg == + "** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" 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" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - # Make sure we don't log a stacktrace - refute output =~ "lib/bandit/pipeline.ex:" + assert msg == + "** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" end + @tag :capture_log test "stream errors are verbosely logged if so configured", context do context = context @@ -146,20 +135,14 @@ 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) - - assert output =~ - "[error] ** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" + # 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} - # Make sure we log a stacktrace - assert output =~ "lib/bandit/pipeline.ex:" + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + 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,66 +154,62 @@ 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_receive {:log, %{level: :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(1500) + Process.sleep(110) assert Transport.recv(socket, 0) == {:error, :closed} end test "it should shut down the connection after read timeout has been reached with no data sent", context do + context = https_server(context, thousand_island_options: [read_timeout: 100]) socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) - Process.sleep(1500) + 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.ConnectionError) Connection count exceeded" end end @@ -238,7 +217,7 @@ defmodule HTTP2ProtocolTest do test "the server should send a SETTINGS frame at start of the connection", context do socket = SimpleH2Client.tls_client(context) Transport.send(socket, "PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n") - assert SimpleH2Client.recv_frame(socket) == {:ok, 4, 0, 0, <<>>} + assert SimpleH2Client.recv_frame(socket) == {:ok, :settings, 0, 0, <<>>} end test "the server respects SETTINGS_MAX_FRAME_SIZE as sent by the client", context do @@ -249,10 +228,10 @@ defmodule HTTP2ProtocolTest do SimpleH2Client.recv_headers(socket) expected = String.duplicate("a", 20_000) - assert {:ok, 0, 0, 1, ^expected} = SimpleH2Client.recv_frame(socket) - assert {:ok, 0, 0, 1, ^expected} = SimpleH2Client.recv_frame(socket) + assert {:ok, :data, 0, 1, ^expected} = SimpleH2Client.recv_frame(socket) + assert {:ok, :data, 0, 1, ^expected} = SimpleH2Client.recv_frame(socket) expected = String.duplicate("a", 10_000) - assert {:ok, 0, 1, 1, ^expected} = SimpleH2Client.recv_frame(socket) + assert {:ok, :data, 1, 1, ^expected} = SimpleH2Client.recv_frame(socket) end def send_50k(conn) do @@ -1046,19 +1025,17 @@ 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.ConnectionError) Received DATA in idle state" end test "reads a one frame body if one frame is sent", context do @@ -1118,131 +1095,124 @@ 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) - 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) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" + assert msg == + "** (Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" + assert msg == + "** (Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" 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) - 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) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" + assert msg == + "** (Bandit.HTTP2.Errors.StreamError) invalid content-length header (RFC9112§6.3.5)" 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) - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) Received END_STREAM with byte still pending" + assert msg == + "** (Bandit.HTTP2.Errors.StreamError) Received END_STREAM with byte still pending" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg == + "** (Bandit.HTTP2.Errors.ConnectionError) DATA frame with zero stream_id (RFC9113§6.1)" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.ConnectionError) Received invalid stream identifier" end end @@ -1288,10 +1258,10 @@ defmodule HTTP2ProtocolTest do # We assume that 60k of random data will get hpacked down into somewhere # between 49152 and 65536 bytes, so we'll need 3 packets total - {:ok, 1, 0, 1, fragment_1} = SimpleH2Client.recv_frame(socket) - {:ok, 9, 0, 1, fragment_2} = SimpleH2Client.recv_frame(socket) - {:ok, 9, 0, 1, fragment_3} = SimpleH2Client.recv_frame(socket) - {:ok, 9, 4, 1, fragment_4} = SimpleH2Client.recv_frame(socket) + {:ok, :headers, 0, 1, fragment_1} = SimpleH2Client.recv_frame(socket) + {:ok, :continuation, 0, 1, fragment_2} = SimpleH2Client.recv_frame(socket) + {:ok, :continuation, 0, 1, fragment_3} = SimpleH2Client.recv_frame(socket) + {:ok, :continuation, 4, 1, fragment_4} = SimpleH2Client.recv_frame(socket) {:ok, headers, _ctx} = [fragment_1, fragment_2, fragment_3, fragment_4] @@ -1411,201 +1381,177 @@ 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") - Process.sleep(100) + {: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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Received trailers with pseudo headers" 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} - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) HEADERS frame with zero stream_id (RFC9113§6.2)" + assert msg == + "** (Bandit.HTTP2.Errors.ConnectionError) HEADERS frame with zero stream_id (RFC9113§6.2)" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.ConnectionError) Received invalid stream identifier" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.ConnectionError) Header decode 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Received uppercase header" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Received invalid pseudo header" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Received invalid pseudo header" 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} - assert SimpleH2Client.recv_rst_stream(socket) == {:ok, 1, 1} - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.StreamError) Received pseudo headers after regular one" + assert msg == + "** (Bandit.HTTP2.Errors.StreamError) Received pseudo headers after regular one" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Received connection-specific header" end test "accepts TE header with a value of trailer", context do @@ -1624,173 +1570,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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Received invalid TE header" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :method headers" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :method headers" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :scheme headers" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :scheme headers" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Received empty :path" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Expected 1 :path headers" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Path does not start with /" end test "combines Cookie headers per RFC9113§8.2.3", context do @@ -1884,27 +1814,25 @@ 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.ConnectionError) Received overlong headers" end end @@ -1941,19 +1869,18 @@ 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg == + "** (Bandit.HTTP2.Errors.StreamError) Terminating stream in remote_closed state" end def no_response_get(conn) do @@ -1964,19 +1891,16 @@ 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Terminating stream in open state" end def no_response_post(conn) do @@ -1985,54 +1909,46 @@ 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.ConnectionError) Received RST_STREAM in idle state" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.TransportError) Received RST_STREAM from client: unknown (99)" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.TransportError) Received RST_STREAM from client: unknown (99)" end def write_after_delay(conn) do - Process.sleep(100) + Process.sleep(10) send_resp(conn, 200, "OK") end @@ -2040,28 +1956,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_receive {:log, %{level: :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_receive {:log, %{level: :error}} end def expect_chunk_error(conn) do @@ -2077,24 +1985,23 @@ defmodule HTTP2ProtocolTest do socket = SimpleH2Client.tls_client(context) SimpleH2Client.exchange_prefaces(socket) SimpleH2Client.send_frame(socket, 4, 0, 0, <<>>) - assert {:ok, 4, 1, 0, <<>>} == SimpleH2Client.recv_frame(socket) + assert {:ok, :settings, 1, 0, <<>>} == SimpleH2Client.recv_frame(socket) end 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} - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) PUSH_PROMISE frame received (RFC9113§8.4)" + assert msg == + "** (Bandit.HTTP2.Errors.ConnectionError) PUSH_PROMISE frame received (RFC9113§8.4)" end end @@ -2103,7 +2010,7 @@ defmodule HTTP2ProtocolTest do socket = SimpleH2Client.setup_connection(context) SimpleH2Client.send_frame(socket, 6, 0, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>) - assert {:ok, 6, 1, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>} == SimpleH2Client.recv_frame(socket) + assert {:ok, :ping, 1, 0, <<1, 2, 3, 4, 5, 6, 7, 8>>} == SimpleH2Client.recv_frame(socket) end end @@ -2113,8 +2020,6 @@ defmodule HTTP2ProtocolTest do assert SimpleH2Client.connection_alive?(socket) - Process.sleep(100) - ThousandIsland.stop(context.server_pid) assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 0} @@ -2182,6 +2087,7 @@ defmodule HTTP2ProtocolTest do assert SimpleH2Client.recv_body(socket) == {:ok, 3, true, "OK"} end + @tag :slow test "does not issue a subsequent update until receive window goes below 2^30", context do socket = SimpleH2Client.setup_connection(context) @@ -2434,59 +2340,56 @@ 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} - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) Expected CONTINUATION frame (RFC9113§6.10)" + assert msg == + "** (Bandit.HTTP2.Errors.ConnectionError) Expected CONTINUATION frame (RFC9113§6.10)" 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} - assert SimpleH2Client.recv_goaway_and_close(socket) == {:ok, 0, 1} - Process.sleep(100) - end) + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert output =~ - "(Bandit.HTTP2.Errors.ConnectionError) Expected CONTINUATION frame (RFC9113§6.10)" + assert msg == + "** (Bandit.HTTP2.Errors.ConnectionError) Expected CONTINUATION frame (RFC9113§6.10)" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + + assert msg == + "** (Bandit.HTTP2.Errors.ConnectionError) Received unexpected CONTINUATION frame (RFC9113§6.10)" end end @@ -2542,23 +2445,21 @@ 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Unable to obtain host and port: No host header" end test "derives port from host header", context do @@ -2613,24 +2514,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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTPError) Header contains invalid port" end test "derives port from schema default if no port specified in host header", context do @@ -2748,44 +2647,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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Path contains dot segment" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Path does not start with /" end end @@ -2985,44 +2880,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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Path contains dot segment" 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_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 + assert msg == "** (Bandit.HTTP2.Errors.StreamError) Path does not start with /" end end diff --git a/test/bandit/initial_handler_test.exs b/test/bandit/initial_handler_test.exs index 8e53a8f7..001b96c5 100644 --- a/test/bandit/initial_handler_test.exs +++ b/test/bandit/initial_handler_test.exs @@ -3,8 +3,6 @@ defmodule InitialHandlerTest do use ServerHelpers use ReqHelpers - import ExUnit.CaptureLog - def report_version(conn) do body = "#{get_http_protocol(conn)} #{conn.scheme}" send_resp(conn, 200, body) @@ -94,16 +92,18 @@ defmodule InitialHandlerTest do setup :http_server setup :req_http1_client + @tag :capture_log test "TLS connection is made to a TCP server", context do - warnings = - capture_log(fn -> - base_url = String.replace_prefix(context.req.options.base_url, "http", "https") - _ = Req.get(context.req, url: "/report_version", base_url: base_url) + context = + context + |> http_server(thousand_island_options: [read_timeout: 1000]) + |> Enum.into(context) - Process.sleep(250) - end) + base_url = String.replace_prefix(context.base, "http", "https") + _ = Req.get(context.req, url: "/report_version", base_url: base_url) - assert warnings =~ "Connection that looks like TLS received on a clear channel" + assert_receive {:log, %{level: :warning, msg: {:string, msg}}}, 500 + assert msg == "Connection that looks like TLS received on a clear channel" end end end diff --git a/test/bandit/server_test.exs b/test/bandit/server_test.exs index 68723a35..f6261296 100644 --- a/test/bandit/server_test.exs +++ b/test/bandit/server_test.exs @@ -1,59 +1,61 @@ defmodule ServerTest do - # False due to capture log emptiness check - use ExUnit.Case, async: false + use ExUnit.Case, async: true use ServerHelpers - import ExUnit.CaptureLog + require LoggerHelpers test "server logs connection details at startup" do - logs = - capture_log(fn -> - start_supervised({Bandit, plug: __MODULE__, port: 0, ip: :loopback}) - end) + LoggerHelpers.receive_all_log_events(__MODULE__) + Process.sleep(100) - assert logs =~ - "Running ServerTest with Bandit #{Application.spec(:bandit)[:vsn]} at 127.0.0.1" + start_supervised({Bandit, plug: __MODULE__, port: 0, ip: :loopback}) + + assert_receive {:log, %{level: :info, msg: {:string, msg}}}, 500 + assert msg =~ "Running ServerTest with Bandit #{Application.spec(:bandit)[:vsn]} at 127.0.0.1" end test "startup_log: false arg disables connection detail log at startup" do - logs = - capture_log(fn -> - start_supervised({Bandit, plug: __MODULE__, port: 0, ip: :loopback, startup_log: false}) - end) + LoggerHelpers.receive_all_log_events(__MODULE__) + start_supervised({Bandit, plug: __MODULE__, port: 0, ip: :loopback, startup_log: false}) - assert logs == "" + refute_receive {:log, _} end + @tag :capture_log test "server logs connection error detail log at startup" do + LoggerHelpers.receive_all_log_events(__MODULE__) + Process.sleep(100) + {:ok, {address, port}} = start_supervised!({Bandit, scheme: :http, plug: __MODULE__, port: 0}) |> ThousandIsland.listener_info() - logs = - capture_log(fn -> - assert {:error, _} = start_supervised({Bandit, plug: __MODULE__, port: port, ip: address}) - end) + assert {:error, _} = start_supervised({Bandit, plug: __MODULE__, port: port, ip: address}) + + assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500 - assert logs =~ + assert IO.iodata_to_binary(msg) =~ "Running ServerTest with Bandit #{Application.spec(:bandit)[:vsn]} at http failed, port #{port} already in use" end test "special cases :inet option" do - logs = - capture_log(fn -> - start_supervised({Bandit, [{:plug, __MODULE__}, :inet, {:port, 0}, {:ip, :loopback}]}) - end) + LoggerHelpers.receive_all_log_events(__MODULE__) + Process.sleep(100) - assert logs =~ "at 127.0.0.1" + start_supervised({Bandit, [{:plug, __MODULE__}, :inet, {:port, 0}, {:ip, :loopback}]}) + + assert_receive {:log, %{level: :info, msg: {:string, msg}}}, 500 + assert msg =~ "Running ServerTest with Bandit #{Application.spec(:bandit)[:vsn]} at 127.0.0.1" end test "special cases :inet6 option" do - logs = - capture_log(fn -> - start_supervised({Bandit, [{:plug, __MODULE__}, :inet6, {:port, 0}, {:ip, :loopback}]}) - end) + LoggerHelpers.receive_all_log_events(__MODULE__) + Process.sleep(100) + + start_supervised({Bandit, [{:plug, __MODULE__}, :inet6, {:port, 0}, {:ip, :loopback}]}) - assert logs =~ "at ::1" + assert_receive {:log, %{level: :info, msg: {:string, msg}}}, 500 + assert msg =~ "Running ServerTest with Bandit #{Application.spec(:bandit)[:vsn]} at ::1" end test "can run multiple instances of Bandit" do diff --git a/test/bandit/websocket/autobahn_test.exs b/test/bandit/websocket/autobahn_test.exs index 9e7a6dd2..c4b2c35c 100644 --- a/test/bandit/websocket/autobahn_test.exs +++ b/test/bandit/websocket/autobahn_test.exs @@ -1,7 +1,7 @@ defmodule WebsocketAutobahnTest do use ExUnit.Case, async: true - @moduletag :external_conformance + @moduletag :slow @moduletag timeout: 3_600_000 defmodule EchoWebSock do @@ -19,7 +19,7 @@ defmodule WebsocketAutobahnTest do Plug.Conn.upgrade_adapter(conn, :websocket, {EchoWebSock, :ok, compress: true}) end - @tag capture_log: true + @tag :capture_log test "autobahn test suite" do # We can't use ServerHelpers since we need to bind on all interfaces {:ok, server_pid} = start_supervised({Bandit, plug: __MODULE__, port: 0}) diff --git a/test/bandit/websocket/protocol_test.exs b/test/bandit/websocket/protocol_test.exs index 1b68b243..774a3e75 100644 --- a/test/bandit/websocket/protocol_test.exs +++ b/test/bandit/websocket/protocol_test.exs @@ -116,10 +116,10 @@ defmodule WebSocketProtocolTest do payload = String.duplicate("0123456789", 200_001) SimpleWebSocketClient.send_text_frame(client, payload) - Process.sleep(100) + Process.sleep(500) end) - assert_receive {:error, :max_frame_size_exceeded} + assert_receive {:error, :max_frame_size_exceeded}, 500 assert output =~ "{:deserializing, :max_frame_size_exceeded}" end end @@ -289,12 +289,12 @@ defmodule WebSocketProtocolTest do assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1000::16>>} # Wait a bit and validate that the server is still very much alive - Process.sleep(100) + Process.sleep(10) assert Process.alive?(pid) # Now send our half of the handshake and verify that the server has shut down SimpleWebSocketClient.send_connection_close_frame(client, 1000) - Process.sleep(100) + Process.sleep(10) refute Process.alive?(pid) # Verify that the server didn't send any extraneous frames @@ -321,7 +321,7 @@ defmodule WebSocketProtocolTest do Transport.close(client) # Wait a bit and validate that the server is closed - Process.sleep(100) + Process.sleep(500) refute Process.alive?(pid) end @@ -342,7 +342,7 @@ defmodule WebSocketProtocolTest do assert SimpleWebSocketClient.connection_closed_for_reading?(client) # Wait a bit and validate that the server is closed - Process.sleep(100) + Process.sleep(500) refute Process.alive?(pid) end @@ -366,7 +366,7 @@ defmodule WebSocketProtocolTest do assert SimpleWebSocketClient.connection_closed_for_reading?(client) # Wait a bit and validate that the server is closed - Process.sleep(100) + Process.sleep(500) refute Process.alive?(pid) end end @@ -382,14 +382,14 @@ defmodule WebSocketProtocolTest do SimpleWebSocketClient.send_continuation_frame(client, <<1, 2, 3>>) # Get the error that terminate saw, to ensure we're closing for the expected reason - assert_receive {:error, "Received unexpected continuation frame (RFC6455§5.4)"} + assert_receive {:error, "Received unexpected continuation frame (RFC6455§5.4)"}, 500 # Validate that the server has started the shutdown handshake from RFC6455§7.1.2 assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1002::16>>} # Verify that the server didn't send any extraneous frames assert SimpleWebSocketClient.connection_closed_for_reading?(client) - Process.sleep(100) + Process.sleep(500) end) assert output =~ "Received unexpected continuation frame (RFC6455§5.4)" @@ -406,13 +406,13 @@ defmodule WebSocketProtocolTest do SimpleWebSocketClient.send_text_frame(client, <<1, 2, 3>>) # Get the error that terminate saw, to ensure we're closing for the expected reason - assert_receive {:error, "Received unexpected text frame (RFC6455§5.4)"} + assert_receive {:error, "Received unexpected text frame (RFC6455§5.4)"}, 500 assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1002::16>>} # Verify that the server didn't send any extraneous frames assert SimpleWebSocketClient.connection_closed_for_reading?(client) - Process.sleep(100) + Process.sleep(500) end) assert output =~ "Received unexpected text frame (RFC6455§5.4)" @@ -429,14 +429,14 @@ defmodule WebSocketProtocolTest do SimpleWebSocketClient.send_binary_frame(client, <<1, 2, 3>>) # Get the error that terminate saw, to ensure we're closing for the expected reason - assert_receive {:error, "Received unexpected binary frame (RFC6455§5.4)"} + assert_receive {:error, "Received unexpected binary frame (RFC6455§5.4)"}, 500 # Validate that the server has started the shutdown handshake from RFC6455§7.1.2 assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1002::16>>} # Verify that the server didn't send any extraneous frames assert SimpleWebSocketClient.connection_closed_for_reading?(client) - Process.sleep(100) + Process.sleep(500) end) assert output =~ "Received unexpected binary frame (RFC6455§5.4)" @@ -452,14 +452,14 @@ defmodule WebSocketProtocolTest do SimpleWebSocketClient.send_text_frame(client, deflated_payload, 0xC) # Get the error that terminate saw, to ensure we're closing for the expected reason - assert_receive {:error, "Received unexpected compressed frame (RFC6455§5.2)"} + assert_receive {:error, "Received unexpected compressed frame (RFC6455§5.2)"}, 500 # Validate that the server has started the shutdown handshake from RFC6455§7.1.2 assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1002::16>>} # Verify that the server didn't send any extraneous frames assert SimpleWebSocketClient.connection_closed_for_reading?(client) - Process.sleep(100) + Process.sleep(500) end) assert output =~ "Received unexpected compressed frame (RFC6455§5.2)" @@ -475,14 +475,14 @@ defmodule WebSocketProtocolTest do SimpleWebSocketClient.send_text_frame(client, deflated_payload, 0xC) # Get the error that terminate saw, to ensure we're closing for the expected reason - assert_receive {:error, "Inflation error"} + assert_receive {:error, "Inflation error"}, 500 # Validate that the server has started the shutdown handshake from RFC6455§7.1.2 assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1007::16>>} # Verify that the server didn't send any extraneous frames assert SimpleWebSocketClient.connection_closed_for_reading?(client) - Process.sleep(100) + Process.sleep(500) end) assert output =~ "Inflation error" @@ -497,14 +497,14 @@ defmodule WebSocketProtocolTest do SimpleWebSocketClient.send_text_frame(client, <<0xE2::8, 0x82::8, 0x28::8>>) # Get the error that terminate saw, to ensure we're closing for the expected reason - assert_receive {:error, "Received non UTF-8 text frame (RFC6455§8.1)"} + assert_receive {:error, "Received non UTF-8 text frame (RFC6455§8.1)"}, 500 # Validate that the server has started the shutdown handshake from RFC6455§7.1.2 assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1007::16>>} # Verify that the server didn't send any extraneous frames assert SimpleWebSocketClient.connection_closed_for_reading?(client) - Process.sleep(100) + Process.sleep(500) end) assert output =~ "Received non UTF-8 text frame (RFC6455§8.1)" @@ -520,14 +520,14 @@ defmodule WebSocketProtocolTest do SimpleWebSocketClient.send_continuation_frame(client, <<0x82::8, 0x28::8>>) # Get the error that terminate saw, to ensure we're closing for the expected reason - assert_receive {:error, "Received non UTF-8 text frame (RFC6455§8.1)"} + assert_receive {:error, "Received non UTF-8 text frame (RFC6455§8.1)"}, 500 # Validate that the server has started the shutdown handshake from RFC6455§7.1.2 assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1007::16>>} # Verify that the server didn't send any extraneous frames assert SimpleWebSocketClient.connection_closed_for_reading?(client) - Process.sleep(100) + Process.sleep(500) end) assert output =~ "Received non UTF-8 text frame (RFC6455§8.1)" @@ -597,11 +597,11 @@ defmodule WebSocketProtocolTest do assert SimpleWebSocketClient.recv_connection_close_frame(client) == {:ok, <<1000::16>>} # Wait a bit and validate that the server is still very much alive - Process.sleep(100) + Process.sleep(10) assert Process.alive?(pid) # Now wait for the server to timeout - Process.sleep(1500) + Process.sleep(110) # Verify that the server has shut down refute Process.alive?(pid) diff --git a/test/bandit/websocket/sock_test.exs b/test/bandit/websocket/sock_test.exs index d1d11dfe..c23371c7 100644 --- a/test/bandit/websocket/sock_test.exs +++ b/test/bandit/websocket/sock_test.exs @@ -1,6 +1,5 @@ defmodule WebSocketWebSockTest do - # False due to telemetry tests - use ExUnit.Case, async: false + use ExUnit.Case, async: true use ServerHelpers use Machete @@ -1231,7 +1230,7 @@ defmodule WebSocketWebSockTest do # Get the websock to tell bandit to shut down SimpleWebSocketClient.send_text_frame(client, "normal") - assert_receive :normal + assert_receive :normal, 500 end test "is called with {:error, reason} on an error connection shutdown", context do @@ -1243,7 +1242,7 @@ defmodule WebSocketWebSockTest do # Get the websock to tell bandit to shut down SimpleWebSocketClient.send_text_frame(client, "boom") - assert_receive {:error, :boom} + assert_receive {:error, :boom}, 500 Process.sleep(100) end) @@ -1257,7 +1256,7 @@ defmodule WebSocketWebSockTest do # Shut the server down in an orderly manner ThousandIsland.stop(context.server_pid) - assert_receive :shutdown + assert_receive :shutdown, 500 end test "is called with :remote on a normal remote shutdown", context do @@ -1266,7 +1265,7 @@ defmodule WebSocketWebSockTest do SimpleWebSocketClient.send_connection_close_frame(client, 1000) - assert_receive :remote + assert_receive :remote, 500 end test "is called with {:error, reason} on a protocol error", context do @@ -1275,7 +1274,7 @@ defmodule WebSocketWebSockTest do Transport.close(client) - assert_receive {:error, :closed} + assert_receive {:error, :closed}, 500 end test "is called with :timeout on a timeout", context do @@ -1295,28 +1294,25 @@ defmodule WebSocketWebSockTest do end test "it should send `start` events on websocket connection", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :websocket, :start]]}) + TelemetryHelpers.attach_all_events(TelemetrySock) client = SimpleWebSocketClient.tcp_client(context) SimpleWebSocketClient.http1_handshake(client, TelemetrySock) - Process.sleep(100) - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :websocket, :start], - %{monotonic_time: integer(), compress: maybe(boolean())}, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - websock: TelemetrySock - }} - ] + assert_receive {:telemetry, [:bandit, :websocket, :start], measurements, metadata}, 500 + + assert measurements ~> %{monotonic_time: integer(), compress: maybe(boolean())} + + assert metadata + ~> %{ + websock: TelemetrySock, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference() + } end test "it should gather send and recv metrics for inclusion in `stop` events", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :websocket, :stop]]}) + TelemetryHelpers.attach_all_events(TelemetrySock) client = SimpleWebSocketClient.tcp_client(context) SimpleWebSocketClient.http1_handshake(client, TelemetrySock) @@ -1325,138 +1321,134 @@ defmodule WebSocketWebSockTest do SimpleWebSocketClient.send_ping_frame(client, "123456") SimpleWebSocketClient.send_pong_frame(client, "1234567") SimpleWebSocketClient.send_connection_close_frame(client, 1000) - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :websocket, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - recv_text_frame_count: 1, - recv_text_frame_bytes: 4, - recv_binary_frame_count: 1, - recv_binary_frame_bytes: 5, - recv_ping_frame_count: 1, - recv_ping_frame_bytes: 6, - recv_pong_frame_count: 1, - recv_pong_frame_bytes: 7, - recv_connection_close_frame_count: 1, - recv_connection_close_frame_bytes: 0, - send_text_frame_count: 1, - send_text_frame_bytes: 4, - send_binary_frame_count: 1, - send_binary_frame_bytes: 5, - send_pong_frame_count: 1, - send_pong_frame_bytes: 6 - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - websock: TelemetrySock - }} - ] + + assert_receive {:telemetry, [:bandit, :websocket, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + recv_text_frame_count: 1, + recv_text_frame_bytes: 4, + recv_binary_frame_count: 1, + recv_binary_frame_bytes: 5, + recv_ping_frame_count: 1, + recv_ping_frame_bytes: 6, + recv_pong_frame_count: 1, + recv_pong_frame_bytes: 7, + recv_connection_close_frame_count: 1, + recv_connection_close_frame_bytes: 0, + send_text_frame_count: 1, + send_text_frame_bytes: 4, + send_binary_frame_count: 1, + send_binary_frame_bytes: 5, + send_pong_frame_count: 1, + send_pong_frame_bytes: 6 + } + + assert metadata + ~> %{ + websock: TelemetrySock, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference() + } end test "it should send `stop` events on normal websocket client disconnection", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :websocket, :stop]]}) + TelemetryHelpers.attach_all_events(TelemetrySock) client = SimpleWebSocketClient.tcp_client(context) SimpleWebSocketClient.http1_handshake(client, TelemetrySock) SimpleWebSocketClient.send_connection_close_frame(client, 1000) - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :websocket, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - recv_connection_close_frame_count: 1, - recv_connection_close_frame_bytes: 0 - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - websock: TelemetrySock - }} - ] + + assert_receive {:telemetry, [:bandit, :websocket, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + recv_connection_close_frame_count: 1, + recv_connection_close_frame_bytes: 0 + } + + assert metadata + ~> %{ + websock: TelemetrySock, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference() + } end test "it should send `stop` events on normal websocket server disconnection", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :websocket, :stop]]}) + TelemetryHelpers.attach_all_events(TelemetrySock) client = SimpleWebSocketClient.tcp_client(context) SimpleWebSocketClient.http1_handshake(client, TelemetrySock) SimpleWebSocketClient.send_text_frame(client, "close") - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :websocket, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - recv_text_frame_count: 1, - recv_text_frame_bytes: 5 - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - websock: TelemetrySock - }} - ] + + assert_receive {:telemetry, [:bandit, :websocket, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + recv_text_frame_count: 1, + recv_text_frame_bytes: 5 + } + + assert metadata + ~> %{ + websock: TelemetrySock, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference() + } end test "it should send `stop` events on normal server shutdown", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :websocket, :stop]]}) + TelemetryHelpers.attach_all_events(TelemetrySock) client = SimpleWebSocketClient.tcp_client(context) SimpleWebSocketClient.http1_handshake(client, TelemetrySock) ThousandIsland.stop(context.server_pid) - Process.sleep(100) - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :websocket, :stop], %{monotonic_time: integer(), duration: integer()}, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - websock: TelemetrySock - }} - ] + assert_receive {:telemetry, [:bandit, :websocket, :stop], measurements, metadata}, 500 + + assert measurements ~> %{monotonic_time: integer(), duration: integer()} + + assert metadata + ~> %{ + websock: TelemetrySock, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference() + } end test "it should send `stop` events on abnormal websocket server disconnection", context do output = capture_log(fn -> - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :websocket, :stop]]}) + TelemetryHelpers.attach_all_events(TelemetrySock) client = SimpleWebSocketClient.tcp_client(context) SimpleWebSocketClient.http1_handshake(client, TelemetrySock) SimpleWebSocketClient.send_text_frame(client, "abnormal_close") - Process.sleep(100) - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :websocket, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - recv_text_frame_count: 1, - recv_text_frame_bytes: 14 - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - websock: TelemetrySock, - error: :nope - }} - ] + assert_receive {:telemetry, [:bandit, :websocket, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + recv_text_frame_count: 1, + recv_text_frame_bytes: 14 + } + + assert metadata + ~> %{ + websock: TelemetrySock, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + error: :nope + } Process.sleep(100) end) @@ -1465,23 +1457,24 @@ defmodule WebSocketWebSockTest do end test "it should send `stop` events on timeout", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :websocket, :stop]]}) + context = http_server(context, thousand_island_options: [read_timeout: 100]) + TelemetryHelpers.attach_all_events(TelemetrySock) client = SimpleWebSocketClient.tcp_client(context) SimpleWebSocketClient.http1_handshake(client, TelemetrySock) - Process.sleep(1100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :websocket, :stop], %{monotonic_time: integer(), duration: integer()}, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - websock: TelemetrySock, - error: :timeout - }} - ] + Process.sleep(110) + + assert_receive {:telemetry, [:bandit, :websocket, :stop], measurements, metadata}, 500 + + assert measurements ~> %{monotonic_time: integer(), duration: integer()} + + assert metadata + ~> %{ + websock: TelemetrySock, + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + error: :timeout + } end end end diff --git a/test/bandit/websocket/upgrade_test.exs b/test/bandit/websocket/upgrade_test.exs index 77ce56a4..b65f715b 100644 --- a/test/bandit/websocket/upgrade_test.exs +++ b/test/bandit/websocket/upgrade_test.exs @@ -1,6 +1,5 @@ defmodule WebSocketUpgradeTest do - # False due to log & telemetry capture - use ExUnit.Case, async: false + use ExUnit.Case, async: true use ServerHelpers use Machete @@ -70,29 +69,25 @@ defmodule WebSocketUpgradeTest do end test "emits HTTP telemetry on upgrade", context do - {:ok, collector_pid} = - start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :stop]]}) - client = SimpleWebSocketClient.tcp_client(context) SimpleWebSocketClient.http1_handshake(client, MyNoopWebSock) - Process.sleep(100) - - assert Bandit.TelemetryCollector.get_events(collector_pid) - ~> [ - {[:bandit, :request, :stop], - %{ - monotonic_time: integer(), - duration: integer(), - req_header_end_time: integer() - }, - %{ - connection_telemetry_span_context: reference(), - telemetry_span_context: reference(), - conn: struct_like(Plug.Conn, []), - plug: {__MODULE__, []} - }} - ] + assert_receive {:telemetry, [:bandit, :request, :stop], measurements, metadata}, 500 + + assert measurements + ~> %{ + monotonic_time: integer(), + duration: integer(), + req_header_end_time: integer() + } + + assert metadata + ~> %{ + connection_telemetry_span_context: reference(), + telemetry_span_context: reference(), + conn: struct_like(Plug.Conn, []), + plug: {__MODULE__, []} + } end end end diff --git a/test/support/test_helpers.ex b/test/support/date_helpers.ex similarity index 91% rename from test/support/test_helpers.ex rename to test/support/date_helpers.ex index b4506abb..9716c515 100644 --- a/test/support/test_helpers.ex +++ b/test/support/date_helpers.ex @@ -1,4 +1,4 @@ -defmodule TestHelpers do +defmodule DateHelpers do @moduledoc false @regex ~r/(?:Mon|Tue|Wed|Thu|Fri|Sat|Sun), (?:[0-2][0-9]|3[0-1]) (?:Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec) \d{4} (?:[0-1][0-9]|2[0-3]):[0-5][0-9]:[0-5][0-9] GMT/ diff --git a/test/support/logger_helpers.ex b/test/support/logger_helpers.ex new file mode 100644 index 00000000..c00b2df7 --- /dev/null +++ b/test/support/logger_helpers.ex @@ -0,0 +1,25 @@ +defmodule LoggerHelpers do + @moduledoc false + + defmacro receive_all_log_events(plug_or_sock) do + quote do + # Yes, this burns atoms but logger needs atoms for refs. See note below about at_exit + ref = make_ref() |> inspect() |> String.to_atom() + + :logger.add_handler(ref, LoggerHelpers, %{ + config: %{pid: self(), plug: unquote(plug_or_sock)} + }) + + # Ideally we'd have an at_exit hook that calls remove_handler but it seems to be racy inside + # logger if we do so + end + end + + def log(%{meta: %{plug: {plug, _}}} = log_event, %{config: %{pid: pid, plug: plug}}), + do: send(pid, {:log, log_event}) + + def log(%{meta: %{websock: websock}} = log_event, %{config: %{pid: pid, websock: websock}}), + do: send(pid, {:log, log_event}) + + def log(_log_event, _config), do: :ok +end diff --git a/test/support/req_helpers.ex b/test/support/req_helpers.ex index da8e8a79..3547498e 100644 --- a/test/support/req_helpers.ex +++ b/test/support/req_helpers.ex @@ -4,16 +4,18 @@ defmodule ReqHelpers do defmacro __using__(_) do quote location: :keep do def req_http1_client(context) do - start_finch(context) - [req: build_req(context)] + name = Module.concat(context.case, context.test) + start_finch(name) + [req: build_req(base_url: context.base, finch: name)] end def req_h2_client(context) do - start_finch(context, protocols: [:http2]) - [req: build_req(context)] + name = Module.concat(context.case, context.test) + start_finch(name, protocols: [:http2]) + [req: build_req(base_url: context.base, finch: name)] end - defp start_finch(context, overrides \\ []) do + defp start_finch(name, overrides \\ []) do options = [ conn_opts: [ @@ -25,17 +27,14 @@ defmodule ReqHelpers do ] |> Keyword.merge(overrides) - start_supervised!({Finch, name: context.test, pools: %{default: options}}) + start_supervised!({Finch, name: name, pools: %{default: options}}) end - defp build_req(context) do + defp build_req(opts) do Req.Request.new([]) |> Req.Request.append_request_steps(base_url: &Req.Steps.put_base_url/1) |> Req.Request.register_options([:base_url, :finch]) - |> Req.Request.merge_options( - base_url: context.base, - finch: context.test - ) + |> Req.Request.merge_options(opts) end end end diff --git a/test/support/server_helpers.ex b/test/support/server_helpers.ex index 0d9592a6..fddfb8b0 100644 --- a/test/support/server_helpers.ex +++ b/test/support/server_helpers.ex @@ -5,39 +5,45 @@ defmodule ServerHelpers do quote location: :keep do import Plug.Conn - def http_server(context, opts \\ []) do - {:ok, server_pid} = - [ - plug: __MODULE__, - port: 0, - ip: :loopback, - thousand_island_options: [read_timeout: 1000] - ] - |> Keyword.merge(opts) - |> Bandit.child_spec() - |> start_supervised() + require LoggerHelpers + require TelemetryHelpers - {:ok, {_ip, port}} = ThousandIsland.listener_info(server_pid) - [base: "http://localhost:#{port}", port: port, server_pid: server_pid] + def http_server(context, opts \\ []) do + [ + plug: __MODULE__, + scheme: :http, + port: 0, + ip: :loopback, + thousand_island_options: [read_timeout: 100] + ] + |> start_server(opts) end def https_server(context, opts \\ []) do + [ + plug: __MODULE__, + scheme: :https, + port: 0, + ip: :loopback, + certfile: Path.join(__DIR__, "../support/cert.pem") |> Path.expand(), + keyfile: Path.join(__DIR__, "../support/key.pem") |> Path.expand(), + thousand_island_options: [read_timeout: 100] + ] + |> start_server(opts) + end + + defp start_server(config, opts) do {:ok, server_pid} = - [ - plug: __MODULE__, - scheme: :https, - port: 0, - ip: :loopback, - certfile: Path.join(__DIR__, "../support/cert.pem") |> Path.expand(), - keyfile: Path.join(__DIR__, "../support/key.pem") |> Path.expand(), - thousand_island_options: [read_timeout: 1000] - ] + config |> Keyword.merge(opts) |> Bandit.child_spec() |> start_supervised() + TelemetryHelpers.attach_all_events(__MODULE__) + LoggerHelpers.receive_all_log_events(__MODULE__) + {:ok, {_ip, port}} = ThousandIsland.listener_info(server_pid) - [base: "https://localhost:#{port}", port: port, server_pid: server_pid] + [base: "#{config[:scheme]}://localhost:#{port}", port: port, server_pid: server_pid] end def init(opts) do diff --git a/test/support/simple_h2_client.ex b/test/support/simple_h2_client.ex index b0fdf6a0..f615ec8a 100644 --- a/test/support/simple_h2_client.ex +++ b/test/support/simple_h2_client.ex @@ -100,34 +100,45 @@ defmodule SimpleH2Client do end def recv_body(socket) do - with {:ok, 0, flags, stream_id, body} <- recv_frame(socket) do - {:ok, stream_id, (flags &&& 0x01) == 0x01, body} + case recv_frame(socket) do + {:ok, :data, flags, stream_id, body} -> {:ok, stream_id, (flags &&& 0x01) == 0x01, body} + other -> unexpected_frame!(other) end end def recv_headers(socket, ctx \\ HPAX.new(4096)) do - with {:ok, 1, flags, stream_id, header_block} <- recv_frame(socket) do - {:ok, headers, ctx} = HPAX.decode(header_block, ctx) - {:ok, stream_id, (flags &&& 0x01) == 0x01, headers, ctx} + case recv_frame(socket) do + {:ok, :headers, flags, stream_id, header_block} -> + {:ok, headers, ctx} = HPAX.decode(header_block, ctx) + {:ok, stream_id, (flags &&& 0x01) == 0x01, headers, ctx} + + other -> + unexpected_frame!(other) end end def recv_rst_stream(socket) do - with {:ok, 3, 0, stream_id, <>} <- recv_frame(socket) do - {:ok, stream_id, error_code} + case recv_frame(socket) do + {:ok, :rst_stream, 0, stream_id, <>} -> {:ok, stream_id, error_code} + other -> unexpected_frame!(other) end end def recv_goaway_and_close(socket) do - with {:ok, 7, 0, 0, <>} <- recv_frame(socket) do - {:error, :closed} = Transport.recv(socket, 0) - {:ok, last_stream_id, error_code} + case recv_frame(socket) do + {:ok, :goaway, 0, 0, <>} -> + {:error, :closed} = Transport.recv(socket, 0) + {:ok, last_stream_id, error_code} + + other -> + unexpected_frame!(other) end end def recv_window_update(socket) do - with {:ok, 8, 0, stream_id, <<0::1, update::31>>} <- recv_frame(socket) do - {:ok, stream_id, update} + case recv_frame(socket) do + {:ok, :window_update, 0, stream_id, <<0::1, update::31>>} -> {:ok, stream_id, update} + other -> unexpected_frame!(other) end end @@ -136,11 +147,27 @@ defmodule SimpleH2Client do Transport.recv(socket, 9) do if body_length > 0 do with {:ok, body} <- Transport.recv(socket, body_length) do - {:ok, type, flags, stream_id, body} + {:ok, map_type(type), flags, stream_id, body} end else - {:ok, type, flags, stream_id, <<>>} + {:ok, map_type(type), flags, stream_id, <<>>} end end end + + def map_type(0), do: :data + def map_type(1), do: :headers + def map_type(2), do: :priority + def map_type(3), do: :rst_stream + def map_type(4), do: :settings + def map_type(5), do: :push_promise + def map_type(6), do: :ping + def map_type(7), do: :goaway + def map_type(8), do: :window_update + def map_type(9), do: :continuation + + @spec unexpected_frame!(term()) :: no_return() + def unexpected_frame!({:ok, type, _flags, _stream_id, _body}) do + raise "Received unexpected frame #{type}" + end end diff --git a/test/support/telemetry_collector.ex b/test/support/telemetry_collector.ex deleted file mode 100644 index f688efca..00000000 --- a/test/support/telemetry_collector.ex +++ /dev/null @@ -1,38 +0,0 @@ -defmodule Bandit.TelemetryCollector do - @moduledoc false - - use GenServer - - def start_link(event_names) do - GenServer.start_link(__MODULE__, event_names) - end - - def record_event(event, measurements, metadata, pid) do - GenServer.cast(pid, {:event, event, measurements, metadata}) - end - - def get_events(pid) do - GenServer.call(pid, :get_events) - end - - def init(event_names) do - # Use __MODULE__ here to keep telemetry from warning about passing a local capture - # https://hexdocs.pm/telemetry/telemetry.html#attach/4 - :telemetry.attach_many( - "#{inspect(self())}.trace", - event_names, - &__MODULE__.record_event/4, - self() - ) - - {:ok, []} - end - - def handle_cast({:event, event, measurements, metadata}, events) do - {:noreply, [{event, measurements, metadata} | events]} - end - - def handle_call(:get_events, _from, events) do - {:reply, Enum.reverse(events), events} - end -end diff --git a/test/support/telemetry_helpers.ex b/test/support/telemetry_helpers.ex new file mode 100644 index 00000000..53fc842f --- /dev/null +++ b/test/support/telemetry_helpers.ex @@ -0,0 +1,34 @@ +defmodule TelemetryHelpers do + @moduledoc false + + defmacro attach_all_events(plug_or_websock) do + events = [ + [:bandit, :request, :start], + [:bandit, :request, :stop], + [:bandit, :request, :exception], + [:bandit, :websocket, :start], + [:bandit, :websocket, :stop] + ] + + quote do + ref = make_ref() + + :telemetry.attach_many( + ref, + unquote(events), + &TelemetryHelpers.handle_event/4, + {self(), unquote(plug_or_websock)} + ) + + on_exit(fn -> :telemetry.detach(ref) end) + end + end + + def handle_event(event, measurements, %{plug: {plug, _}} = metadata, {pid, plug}), + do: send(pid, {:telemetry, event, measurements, metadata}) + + def handle_event(event, measurements, %{websock: websock} = metadata, {pid, websock}), + do: send(pid, {:telemetry, event, measurements, metadata}) + + def handle_event(_event, _measurements, _metadata, {_pid, _plug_or_websock}), do: :ok +end diff --git a/test/test_helper.exs b/test/test_helper.exs index 9829622c..fbede0df 100644 --- a/test/test_helper.exs +++ b/test/test_helper.exs @@ -1,4 +1,4 @@ -ExUnit.start(exclude: :external_conformance) +ExUnit.start(exclude: :slow) # Capture all logs so we're able to assert on logging done at info level in tests Logger.configure(level: :debug)