diff --git a/lib/sentry/test/assertions.ex b/lib/sentry/test/assertions.ex index a1813b93..c518ba3d 100644 --- a/lib/sentry/test/assertions.ex +++ b/lib/sentry/test/assertions.ex @@ -29,11 +29,30 @@ defmodule Sentry.Test.Assertions do events = Sentry.Test.pop_sentry_reports() event = find_sentry_report!(events, message: %{formatted: ~r/hello/}) + ## Awaiting Asynchronous Reports + + Log and metric events flow through the `Sentry.TelemetryProcessor` pipeline + asynchronously. The type-form of `assert_sentry_report/2` and + `assert_sentry_log/3` await internally — they flush the telemetry pipeline + and poll the collector with exponential backoff until at least one matching + item is captured, up to a timeout (default `#{1000}ms`). + + Tests typically do not need to call `Sentry.TelemetryProcessor.flush/0` + or `Process.sleep/1` before these assertions. + + Override the default via the reserved `:timeout` keyword: + + assert_sentry_report(:log, [level: :info, body: "hi"], timeout: 2000) + assert_sentry_log(:info, "hi", timeout: 2000) + """ @moduledoc since: "12.1.0" import ExUnit.Assertions, only: [flunk: 1] + @default_timeout 1000 + @max_poll_interval 50 + @type_to_pop %{ event: &Sentry.Test.pop_sentry_reports/0, transaction: &Sentry.Test.pop_sentry_transactions/0, @@ -97,10 +116,11 @@ defmodule Sentry.Test.Assertions do @spec assert_sentry_report(:event | :transaction | :log | :metric, keyword()) :: Sentry.Event.t() | Sentry.Transaction.t() | Sentry.LogEvent.t() | Sentry.Metric.t() def assert_sentry_report(type, criteria) when type in [:event, :transaction, :log, :metric] do - items = pop_for_type(type) + {timeout, criteria} = Keyword.pop(criteria, :timeout, @default_timeout) label = type_label(type) - item = unwrap_single!(items, label) + items = await_items(type, timeout, &(length(&1) >= 1)) + item = unwrap_single!(items, label, timeout) assert_fields!(item, criteria, label) item end @@ -117,12 +137,17 @@ defmodule Sentry.Test.Assertions do @doc """ Asserts that a log was captured matching the given level and body pattern. - Pops all collected logs and finds the first one matching `level` and - `body_pattern`. This uses find semantics (not assert-exactly-1) because - logs often come in batches. + Awaits asynchronously-captured logs: the pipeline is flushed and the + collector is polled until a log matching the criteria is found or the + timeout elapses (default `#{1000}ms`, overridable via the `:timeout` + reserved key in `extra_criteria`). + + Once at least one candidate log is available, finds the first one matching + `level` and `body_pattern`. This uses find semantics (not assert-exactly-1) + because logs often come in batches. The optional third argument is a keyword list of extra criteria to match - on any `Sentry.LogEvent` field. + on any `Sentry.LogEvent` field, plus the reserved `:timeout` option. Returns the matched log event. @@ -132,6 +157,7 @@ defmodule Sentry.Test.Assertions do assert_sentry_log(:error, ~r/connection refused/) assert_sentry_log(:info, "User session started", trace_id: "abc123") assert_sentry_log(:info, "User session started", attributes: %{id: 312}) + assert_sentry_log(:info, "slow path", timeout: 2000) """ @doc since: "12.1.0" @@ -139,9 +165,18 @@ defmodule Sentry.Test.Assertions do Sentry.LogEvent.t() def assert_sentry_log(level, body_pattern, extra_criteria \\ []) when is_atom(level) and (is_binary(body_pattern) or is_struct(body_pattern, Regex)) do + {timeout, extra_criteria} = Keyword.pop(extra_criteria, :timeout, @default_timeout) criteria = [level: level, body: body_pattern] ++ extra_criteria - logs = Sentry.Test.pop_sentry_logs() - find_item!(logs, criteria, "log") + + logs = + await_items(:log, timeout, fn items -> + Enum.any?(items, &matches_criteria?(&1, criteria)) + end) + + {match, remaining} = extract_first_match(logs, criteria) + put_inbox(:log, remaining) + + match || flunk(format_find_error(logs, criteria, "log")) end @doc """ @@ -168,15 +203,98 @@ defmodule Sentry.Test.Assertions do Map.fetch!(@type_to_pop, type).() end + # Per-test inbox of unmatched items left over from prior assert_sentry_log + # calls. Destructively read at the start of each await; unmatched items + # are written back by callers that use find semantics. + @inbox_key {__MODULE__, :inbox} + + defp take_inbox(type) do + inbox = Process.get(@inbox_key, %{}) + Process.put(@inbox_key, Map.put(inbox, type, [])) + Map.get(inbox, type, []) + end + + defp put_inbox(type, items) do + inbox = Process.get(@inbox_key, %{}) + Process.put(@inbox_key, Map.put(inbox, type, items)) + :ok + end + + defp await_items(type, timeout, done_fn) do + maybe_flush(timeout) + deadline = System.monotonic_time(:millisecond) + timeout + await_loop(type, deadline, 1, take_inbox(type), done_fn) + end + + defp await_loop(type, deadline, sleep_ms, acc, done_fn) do + acc = acc ++ pop_for_type(type) + + cond do + done_fn.(acc) -> + acc + + System.monotonic_time(:millisecond) >= deadline -> + acc + + true -> + Process.sleep(sleep_ms) + await_loop(type, deadline, min(sleep_ms * 2, @max_poll_interval), acc, done_fn) + end + end + + # Drains the TelemetryProcessor pipeline synchronously. No-op when no + # per-test processor is registered (e.g., tests that bypass the pipeline + # by inserting directly into the collector ETS table). + defp maybe_flush(timeout) do + case Process.get(:sentry_telemetry_processor) do + nil -> + :ok + + processor -> + scheduler = Sentry.TelemetryProcessor.scheduler_name(processor) + + if Process.whereis(scheduler) do + try do + Sentry.TelemetryProcessor.flush(processor, timeout) + catch + :exit, _ -> :ok + end + end + + :ok + end + end + + defp matches_criteria?(item, criteria) do + Enum.all?(criteria, fn {key, expected} -> + match_value?(get_field(item, key), expected) + end) + end + + defp extract_first_match(items, criteria) do + {match, rest_reversed} = + Enum.reduce(items, {nil, []}, fn item, {match, rest} -> + cond do + match != nil -> {match, [item | rest]} + matches_criteria?(item, criteria) -> {item, rest} + true -> {nil, [item | rest]} + end + end) + + {match, Enum.reverse(rest_reversed)} + end + defp type_label(:event), do: "event" defp type_label(:transaction), do: "transaction" defp type_label(:log), do: "log" defp type_label(:metric), do: "metric" - defp unwrap_single!([single], _label), do: single - defp unwrap_single!(item, _label) when is_map(item), do: item + defp unwrap_single!(items_or_item, label, timeout \\ nil) - defp unwrap_single!([], label) do + defp unwrap_single!([single], _label, _timeout), do: single + defp unwrap_single!(item, _label, _timeout) when is_map(item), do: item + + defp unwrap_single!([], label, nil) do flunk(""" Expected exactly 1 Sentry #{label}, got 0. @@ -184,7 +302,17 @@ defmodule Sentry.Test.Assertions do """) end - defp unwrap_single!(list, label) when is_list(list) do + defp unwrap_single!([], label, timeout) do + flunk(""" + Expected 1 Sentry #{label} within #{timeout}ms, got 0. + + Ensure the TelemetryProcessor is running for this test (via Sentry.Case or + Sentry.Test.setup_sentry/1) and that the event was emitted before the + assertion. For slow pipelines, pass a larger `:timeout` option.\ + """) + end + + defp unwrap_single!(list, label, _timeout) when is_list(list) do flunk(""" Expected exactly 1 Sentry #{label}, got #{length(list)}. @@ -210,11 +338,8 @@ defmodule Sentry.Test.Assertions do end defp find_item!(items, criteria, label) do - Enum.find(items, fn item -> - Enum.all?(criteria, fn {key, expected} -> - match_value?(get_field(item, key), expected) - end) - end) || flunk(format_find_error(items, criteria, label)) + Enum.find(items, &matches_criteria?(&1, criteria)) || + flunk(format_find_error(items, criteria, label)) end defp get_field(data, key) when is_atom(key) do diff --git a/test/sentry/logger_handler/logs_test.exs b/test/sentry/logger_handler/logs_test.exs index 898f1a58..135fb544 100644 --- a/test/sentry/logger_handler/logs_test.exs +++ b/test/sentry/logger_handler/logs_test.exs @@ -2,7 +2,9 @@ defmodule Sentry.LoggerHandler.LogsTest do use Sentry.Case, async: false import Sentry.TestHelpers + import Sentry.Test.Assertions + alias Sentry.Test, as: SentryTest alias Sentry.TelemetryProcessor require Logger @@ -11,7 +13,7 @@ defmodule Sentry.LoggerHandler.LogsTest do @moduletag :capture_log setup do - setup_bypass(enable_logs: true, logs: [level: :info]) + SentryTest.setup_sentry(enable_logs: true, logs: [level: :info]) end setup :add_logs_handler @@ -24,38 +26,11 @@ defmodule Sentry.LoggerHandler.LogsTest do end describe "logging with handler" do - test "creates log event and adds to buffer", %{bypass: bypass} do - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, item_header, item_body, _] = String.split(body, "\n") - - item_header_map = decode!(item_header) - assert item_header_map["type"] == "log" - assert item_header_map["item_count"] == 1 - assert item_header_map["content_type"] == "application/vnd.sentry.items.log+json" - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - assert log_event["body"] == "Test log message" - assert log_event["level"] == "info" - assert is_number(log_event["timestamp"]) - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - - initial_size = TelemetryProcessor.buffer_size(:log) - + test "creates log event and adds to buffer" do Logger.info("Test log message") - assert_buffer_size(nil, initial_size + 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + log = assert_sentry_log(:info, "Test log message") + assert is_number(log.timestamp) end test "filters logs below configured level" do @@ -71,47 +46,14 @@ defmodule Sentry.LoggerHandler.LogsTest do assert TelemetryProcessor.buffer_size(:log) == initial_size end - test "accepts logs at or above configured level", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, item_header, item_body, _] = String.split(body, "\n") - - item_header_map = decode!(item_header) - assert item_header_map["type"] == "log" - assert item_header_map["item_count"] == 3 - - item_body_map = decode!(item_body) - assert %{"items" => log_events} = item_body_map - assert length(log_events) == 3 - - assert [info_event, warning_event, error_event] = log_events - assert info_event["level"] == "info" - assert info_event["body"] == "Info message" - assert warning_event["level"] == "warn" - assert warning_event["body"] == "Warning message" - assert error_event["level"] == "error" - assert error_event["body"] == "Error message" - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - - initial_size = TelemetryProcessor.buffer_size(:log) - + test "accepts logs at or above configured level" do Logger.info("Info message") Logger.warning("Warning message") Logger.error("Error message") - assert_buffer_size(nil, initial_size + 3) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + assert_sentry_log(:info, "Info message") + assert_sentry_log(:warn, "Warning message") + assert_sentry_log(:error, "Error message") end test "filters excluded domains" do @@ -137,92 +79,42 @@ defmodule Sentry.LoggerHandler.LogsTest do assert_buffer_size(nil, initial_size + 2) end - test "includes metadata as attributes", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, item_header, item_body, _] = String.split(body, "\n") - - item_header_map = decode!(item_header) - assert item_header_map["type"] == "log" - assert item_header_map["item_count"] == 1 - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - assert log_event["body"] == "Request processed" - - assert %{"request_id" => %{"type" => "string", "value" => "abc123"}} = - log_event["attributes"] - - assert %{"user_id" => %{"type" => "integer", "value" => 42}} = log_event["attributes"] - - refute Map.has_key?(log_event["attributes"], "other_meta") - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - + test "includes metadata as attributes" do put_test_config(logs: [metadata: [:request_id, :user_id]]) - TelemetryProcessor.flush() - Logger.metadata(request_id: "abc123", user_id: 42, other_meta: "should not be included") Logger.info("Request processed") - assert_buffer_size(nil, 1) + log = + assert_sentry_log(:info, "Request processed", + attributes: %{request_id: "abc123", user_id: 42} + ) - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + refute Map.has_key?(log.attributes, :other_meta) end - test "safely serializes struct metadata as string attributes", %{bypass: bypass} do - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - - assert %{"my_uri" => %{"type" => "string", "value" => value}} = - log_event["attributes"] - - assert value == inspect(URI.parse("https://example.com/path")) - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - + test "safely serializes struct metadata as string attributes" do put_test_config(logs: [metadata: [:my_uri]]) - TelemetryProcessor.flush() - - Logger.metadata(my_uri: URI.parse("https://example.com/path")) + uri = URI.parse("https://example.com/path") + Logger.metadata(my_uri: uri) Logger.info("Request with struct metadata") - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + # Structs are stringified via inspect/1 when the envelope is built; the + # collected LogEvent still holds the original struct. + log = assert_sentry_log(:info, "Request with struct metadata") + assert log.attributes[:my_uri] == uri end test "includes all metadata when configured with :all" do put_test_config(logs: [metadata: :all]) - TelemetryProcessor.flush() - Logger.metadata(request_id: "abc123", user_id: 42, custom_field: "value") Logger.info("Request with metadata") - assert_buffer_size(nil, 1) + assert_sentry_log(:info, "Request with metadata", + attributes: %{request_id: "abc123", user_id: 42, custom_field: "value"} + ) end test "does not send logs when enable_logs is false at handler setup time", %{ @@ -299,183 +191,36 @@ defmodule Sentry.LoggerHandler.LogsTest do assert %NimbleOptions.ValidationError{key: :enable_logs} = error end - test "generates trace_id when no trace context is available", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - assert log_event["body"] == "Log without trace" - - assert is_binary(log_event["trace_id"]) - assert String.length(log_event["trace_id"]) == 32 - assert String.match?(log_event["trace_id"], ~r/^[0-9a-f]{32}$/) - - refute Map.has_key?(log_event["attributes"], "sentry.trace.parent_span_id") - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - - TelemetryProcessor.flush() - + test "generates trace_id when no trace context is available" do Logger.info("Log without trace") - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + log = assert_sentry_log(:info, "Log without trace") + assert is_binary(log.trace_id) + assert log.trace_id =~ ~r/^[0-9a-f]{32}$/ end - test "captures message template with %s parameters via Logger metadata", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - - # The body should be the interpolated message - assert log_event["body"] == "User jane_doe logged in from 192.168.1.1" - - # Check for template attribute - assert %{ - "sentry.message.template" => %{ - "type" => "string", - "value" => "User %s logged in from %s" - } - } = log_event["attributes"] - - # Check for parameter attributes - assert %{ - "sentry.message.parameter.0" => %{ - "type" => "string", - "value" => "jane_doe" - } - } = log_event["attributes"] - - assert %{ - "sentry.message.parameter.1" => %{ - "type" => "string", - "value" => "192.168.1.1" - } - } = log_event["attributes"] - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - - TelemetryProcessor.flush() - - # Use Logger with %s template and parameters via metadata + test "captures message template with %s parameters via Logger metadata" do Logger.info("User %s logged in from %s", parameters: ["jane_doe", "192.168.1.1"]) - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + log = assert_sentry_log(:info, "User jane_doe logged in from 192.168.1.1") + assert log.template == "User %s logged in from %s" + assert log.parameters == ["jane_doe", "192.168.1.1"] end - test "captures message template with %{key} named parameters", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - - # The body should be the interpolated message - assert log_event["body"] == "Hello Jane from NYC" - - # Check for template attribute - assert %{ - "sentry.message.template" => %{ - "type" => "string", - "value" => "Hello %{name} from %{city}" - } - } = log_event["attributes"] - - # Parameters are stored in template order - assert %{ - "sentry.message.parameter.0" => %{ - "type" => "string", - "value" => "Jane" - } - } = log_event["attributes"] - - assert %{ - "sentry.message.parameter.1" => %{ - "type" => "string", - "value" => "NYC" - } - } = log_event["attributes"] - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - - TelemetryProcessor.flush() - - # Use Logger with %{key} template and named parameters + test "captures message template with %{key} named parameters" do Logger.info("Hello %{name} from %{city}", parameters: %{name: "Jane", city: "NYC"}) - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + log = assert_sentry_log(:info, "Hello Jane from NYC") + assert log.template == "Hello %{name} from %{city}" + assert log.parameters == ["Jane", "NYC"] end - test "does not include template attributes for plain string messages", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - - assert log_event["body"] == "Simple log message" - - # Should NOT have template or parameter attributes - refute Map.has_key?(log_event["attributes"], "sentry.message.template") - refute Map.has_key?(log_event["attributes"], "sentry.message.parameter.0") - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - - TelemetryProcessor.flush() - + test "does not include template attributes for plain string messages" do Logger.info("Simple log message") - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + log = assert_sentry_log(:info, "Simple log message") + assert is_nil(log.template) + assert is_nil(log.parameters) end end @@ -490,99 +235,17 @@ defmodule Sentry.LoggerHandler.LogsTest do :ok end - test "automatically includes trace context from OpenTelemetry spans", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.stub(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, item_header, item_body, _] = String.split(body, "\n") - - item_header_map = decode!(item_header) - - case item_header_map["type"] do - "log" -> - assert item_header_map["item_count"] == 1 - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - assert log_event["body"] == "Log inside OTel span" - - assert is_binary(log_event["trace_id"]) - assert String.length(log_event["trace_id"]) == 32 - assert String.match?(log_event["trace_id"], ~r/^[0-9a-f]{32}$/) - - span_id = log_event["span_id"] - assert is_binary(span_id) - assert String.length(span_id) == 16 - assert String.match?(span_id, ~r/^[0-9a-f]{16}$/) - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - - "transaction" -> - Plug.Conn.resp(conn, 200, ~s<{"id": "test-txn"}>) - end - end) - - TelemetryProcessor.flush() - + test "automatically includes trace context from OpenTelemetry spans" do Tracer.with_span "test_span" do Logger.info("Log inside OTel span") end - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + log = assert_sentry_log(:info, "Log inside OTel span") + assert log.trace_id =~ ~r/^[0-9a-f]{32}$/ + assert log.span_id =~ ~r/^[0-9a-f]{16}$/ end - test "includes trace context from nested OpenTelemetry spans", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.stub(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, item_header, item_body, _] = String.split(body, "\n") - - item_header_map = decode!(item_header) - - case item_header_map["type"] do - "log" -> - assert item_header_map["item_count"] == 2 - - item_body_map = decode!(item_body) - assert %{"items" => log_events} = item_body_map - assert length(log_events) == 2 - - [parent_log, child_log] = log_events - - assert parent_log["trace_id"] == child_log["trace_id"] - - parent_span_id = parent_log["span_id"] - child_span_id = child_log["span_id"] - - assert is_binary(parent_span_id) - assert is_binary(child_span_id) - assert parent_span_id != child_span_id - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - - "transaction" -> - Plug.Conn.resp(conn, 200, ~s<{"id": "test-txn"}>) - end - end) - - TelemetryProcessor.flush() - - require OpenTelemetry.Tracer, as: Tracer - + test "includes trace context from nested OpenTelemetry spans" do Tracer.with_span "parent_span" do Logger.info("Log in parent span") @@ -591,203 +254,112 @@ defmodule Sentry.LoggerHandler.LogsTest do end end - assert_buffer_size(nil, 2) + parent_log = assert_sentry_log(:info, "Log in parent span") + child_log = assert_sentry_log(:info, "Log in child span") - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + assert parent_log.trace_id == child_log.trace_id + assert parent_log.span_id != child_log.span_id end - test "works out-of-the-box when handler is configured", %{ - bypass: bypass - } do - test_pid = self() - - Bypass.stub(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, item_header, item_body, _] = String.split(body, "\n") - - item_header_map = decode!(item_header) - - case item_header_map["type"] do - "log" -> - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - - assert is_binary(log_event["trace_id"]) - assert String.length(log_event["trace_id"]) == 32 - - assert is_binary(log_event["span_id"]) - - send(test_pid, :envelope_sent) - - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - - "transaction" -> - Plug.Conn.resp(conn, 200, ~s<{"id": "test-txn"}>) - end - end) - - TelemetryProcessor.flush() - + test "works out-of-the-box when handler is configured" do Tracer.with_span "api_call" do Logger.info("Processing API request") end - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + log = assert_sentry_log(:info, "Processing API request") + assert log.trace_id =~ ~r/^[0-9a-f]{32}$/ + assert is_binary(log.span_id) end end describe "before_send_log callback" do - test "allows modifying log events before sending", %{bypass: bypass} do - test_pid = self() + # `put_test_config(before_send_log: ...)` replaces the collector wrapper + # installed by setup_sentry/1, so we install our own wrapper that applies + # the user's logic and writes the (possibly modified) log event directly + # into the test's ETS collector. + defp install_before_send_log(user_fn) do + collector_table = Process.get(:sentry_test_collector) + + apply_fn = fn event -> + case user_fn do + {mod, fun} -> apply(mod, fun, [event]) + fun when is_function(fun, 1) -> fun.(event) + end + end put_test_config( before_send_log: fn log_event -> - %{log_event | attributes: Map.put(log_event.attributes, "custom_attr", "injected")} - end - ) - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map + case apply_fn.(log_event) do + nil -> + nil - assert log_event["attributes"]["custom_attr"] == %{ - "type" => "string", - "value" => "injected" - } + false -> + false - send(test_pid, :envelope_sent) - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) - - Logger.info("Test message") + modified -> + :ets.insert( + collector_table, + {System.unique_integer([:monotonic]), modified} + ) - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 - end - - test "filters out log events when callback returns nil", %{bypass: bypass} do - put_test_config( - before_send_log: fn log_event -> - if String.contains?(log_event.body, "should_be_filtered") do - nil - else - log_event + modified end end ) + end - test_pid = self() + test "allows modifying log events before sending" do + install_before_send_log(fn log_event -> + %{log_event | attributes: Map.put(log_event.attributes, "custom_attr", "injected")} + end) - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") + Logger.info("Test message") - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - assert log_event["body"] == "This message should pass" + log = assert_sentry_log(:info, "Test message") + assert log.attributes["custom_attr"] == "injected" + end - send(test_pid, :envelope_sent) - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) + test "filters out log events when callback returns nil" do + install_before_send_log(fn log_event -> + if String.contains?(log_event.body, "should_be_filtered"), do: nil, else: log_event end) Logger.info("This message should_be_filtered") Logger.info("This message should pass") - assert_buffer_size(nil, 2) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + assert_sentry_log(:info, "This message should pass") + assert SentryTest.pop_sentry_logs() == [] end - test "filters out log events when callback returns false", %{bypass: bypass} do - put_test_config( - before_send_log: fn log_event -> - if String.contains?(log_event.body, "drop_me") do - false - else - log_event - end - end - ) - - test_pid = self() - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - assert log_event["body"] == "Keep this message" - - send(test_pid, :envelope_sent) - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) + test "filters out log events when callback returns false" do + install_before_send_log(fn log_event -> + if String.contains?(log_event.body, "drop_me"), do: false, else: log_event end) Logger.info("drop_me please") Logger.info("Keep this message") - assert_buffer_size(nil, 2) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + assert_sentry_log(:info, "Keep this message") + assert SentryTest.pop_sentry_logs() == [] end - test "supports MFA tuple callback format", %{bypass: bypass} do - test_pid = self() - - put_test_config(before_send_log: {__MODULE__, :before_send_log_callback}) - - Bypass.expect_once(bypass, "POST", "/api/1/envelope/", fn conn -> - {:ok, body, conn} = Plug.Conn.read_body(conn) - [_header, _item_header, item_body, _] = String.split(body, "\n") - - item_body_map = decode!(item_body) - assert %{"items" => [log_event]} = item_body_map - - assert log_event["attributes"]["mfa_added"] == %{ - "type" => "string", - "value" => "true" - } - - send(test_pid, :envelope_sent) - Plug.Conn.resp(conn, 200, ~s<{"id": "test-123"}>) - end) + test "supports MFA tuple callback format" do + install_before_send_log({__MODULE__, :before_send_log_callback}) Logger.info("Test MFA callback") - assert_buffer_size(nil, 1) - - TelemetryProcessor.flush() - - assert_receive :envelope_sent, 1000 + log = assert_sentry_log(:info, "Test MFA callback") + assert log.attributes["mfa_added"] == "true" end - test "does not send any logs when all are filtered", %{} do - put_test_config(before_send_log: fn _log_event -> nil end) + test "does not send any logs when all are filtered" do + install_before_send_log(fn _log_event -> nil end) Logger.info("All messages filtered 1") Logger.info("All messages filtered 2") - assert_buffer_size(nil, 2) - TelemetryProcessor.flush() - - refute_receive _, 100 + assert SentryTest.pop_sentry_logs() == [] end end diff --git a/test/sentry/test/assertions_test.exs b/test/sentry/test/assertions_test.exs index 0b9940d5..31f63217 100644 --- a/test/sentry/test/assertions_test.exs +++ b/test/sentry/test/assertions_test.exs @@ -50,8 +50,8 @@ defmodule Sentry.Test.AssertionsTest do end test "fails when 0 items captured" do - assert_raise ExUnit.AssertionError, ~r/Expected exactly 1 Sentry event, got 0/, fn -> - assert_sentry_report(:event, level: :error) + assert_raise ExUnit.AssertionError, ~r/Expected 1 Sentry event within 10ms, got 0/, fn -> + assert_sentry_report(:event, level: :error, timeout: 10) end end @@ -179,7 +179,7 @@ defmodule Sentry.Test.AssertionsTest do insert_log_event(:info, "other message") assert_raise ExUnit.AssertionError, ~r/No matching Sentry log found/, fn -> - assert_sentry_log(:error, "nonexistent message") + assert_sentry_log(:error, "nonexistent message", timeout: 10) end end @@ -187,7 +187,7 @@ defmodule Sentry.Test.AssertionsTest do insert_log_event(:info, "hello") assert_raise ExUnit.AssertionError, ~r/No matching Sentry log found/, fn -> - assert_sentry_log(:error, "hello") + assert_sentry_log(:error, "hello", timeout: 10) end end end @@ -284,8 +284,8 @@ defmodule Sentry.Test.AssertionsTest do end test "fails when 0 metrics captured" do - assert_raise ExUnit.AssertionError, ~r/Expected exactly 1 Sentry metric, got 0/, fn -> - assert_sentry_report(:metric, name: "button.clicks") + assert_raise ExUnit.AssertionError, ~r/Expected 1 Sentry metric within 10ms, got 0/, fn -> + assert_sentry_report(:metric, name: "button.clicks", timeout: 10) end end @@ -302,6 +302,60 @@ defmodule Sentry.Test.AssertionsTest do end end + describe "await behaviour" do + setup do + SentryTest.setup_sentry() + end + + test "polling catches an item inserted mid-wait" do + table = Process.get(:sentry_test_collector) + + Task.start(fn -> + Process.sleep(30) + event = build_event(level: :error) + :ets.insert(table, {System.unique_integer([:monotonic]), event}) + end) + + assert_sentry_report(:event, level: :error, timeout: 500) + end + + test ":timeout option is respected when item never arrives" do + before = System.monotonic_time(:millisecond) + + assert_raise ExUnit.AssertionError, ~r/within 50ms/, fn -> + assert_sentry_report(:event, level: :error, timeout: 50) + end + + elapsed = System.monotonic_time(:millisecond) - before + assert elapsed < 500, "expected fast failure, waited #{elapsed}ms" + end + + test "assert_sentry_log awaits for a matching log even when non-matching logs arrive first" do + table = Process.get(:sentry_test_collector) + now = System.system_time(:microsecond) / 1_000_000 + + Task.start(fn -> + Process.sleep(10) + noise = struct!(Sentry.LogEvent, level: :info, body: "unrelated", timestamp: now) + :ets.insert(table, {System.unique_integer([:monotonic]), noise}) + + Process.sleep(30) + target = struct!(Sentry.LogEvent, level: :info, body: "target log", timestamp: now) + :ets.insert(table, {System.unique_integer([:monotonic]), target}) + end) + + log = assert_sentry_log(:info, "target log", timeout: 500) + assert log.body == "target log" + end + + test "maybe_flush is a no-op when no processor is registered in pdict" do + refute Process.get(:sentry_telemetry_processor) + + insert_event(level: :error) + assert_sentry_report(:event, level: :error) + end + end + describe "integration with real event pipeline" do setup do SentryTest.setup_sentry() diff --git a/test/sentry/test_test.exs b/test/sentry/test_test.exs index edf82bdf..1ccc91be 100644 --- a/test/sentry/test_test.exs +++ b/test/sentry/test_test.exs @@ -240,8 +240,6 @@ defmodule Sentry.TestTest do Logger.info("pop_sentry_logs test message") - Sentry.TelemetryProcessor.flush() - assert_sentry_log(:info, "pop_sentry_logs test message") end end