From 46f05d81c9554679a771a83647d48dc721625532 Mon Sep 17 00:00:00 2001 From: RobertJoonas <56999674+RobertJoonas@users.noreply.github.com> Date: Mon, 27 Oct 2025 16:50:54 +0000 Subject: [PATCH] Verification / Detection follow-ups (#5836) * make timeout configurable for a check via check_opts * add an internal_check_timeout test case to verification/checks_test.exs * move verification observability tests to a separate file ... make it sync and test capturing Sentry events too * separate detection observability checks too * test sentry events in detection * consider internal check timeouts browserless issues in detection too * test util function defs to ee_only --- .../plausible/installation_support/check.ex | 11 +- .../installation_support/check_runner.ex | 4 +- .../installation_support/checks/detection.ex | 3 - .../checks/verify_installation.ex | 3 - .../checks/verify_installation_cache_bust.ex | 3 - .../installation_support/detection/checks.ex | 18 +- .../detection/diagnostics.ex | 2 +- .../verification/checks.ex | 21 +- .../verification/diagnostics.ex | 2 +- .../installation_support/check_test.exs | 10 +- .../detection/checks_observability_test.exs | 263 ++++++++++++++++++ .../detection/checks_test.exs | 198 +------------ .../checks_observability_test.exs | 188 +++++++++++++ .../verification/checks_test.exs | 101 +------ 14 files changed, 498 insertions(+), 329 deletions(-) create mode 100644 test/plausible/installation_support/detection/checks_observability_test.exs create mode 100644 test/plausible/installation_support/verification/checks_observability_test.exs diff --git a/extra/lib/plausible/installation_support/check.ex b/extra/lib/plausible/installation_support/check.ex index c8367bf6e1..225e0273e5 100644 --- a/extra/lib/plausible/installation_support/check.ex +++ b/extra/lib/plausible/installation_support/check.ex @@ -13,7 +13,6 @@ defmodule Plausible.InstallationSupport.Check do """ @type state() :: Plausible.InstallationSupport.State.t() @callback report_progress_as() :: String.t() - @callback timeout_ms() :: integer() @callback perform(state()) :: state() defmacro __using__(_) do @@ -25,11 +24,9 @@ defmodule Plausible.InstallationSupport.Check do @behaviour Plausible.InstallationSupport.Check - def timeout_ms, do: 10_000 + def perform_safe(state, opts) do + timeout = Keyword.get(opts, :timeout, 10_000) - defoverridable timeout_ms: 0 - - def perform_safe(state) do task = Task.async(fn -> try do @@ -45,7 +42,7 @@ defmodule Plausible.InstallationSupport.Check do end) try do - Task.await(task, timeout_ms()) + Task.await(task, timeout) catch :exit, {:timeout, _} -> Task.shutdown(task, :brutal_kill) @@ -54,7 +51,7 @@ defmodule Plausible.InstallationSupport.Check do put_diagnostics(state, service_error: %{ code: :internal_check_timeout, - extra: "#{check_name} timed out after #{timeout_ms()}ms" + extra: "#{check_name} timed out after #{timeout}ms" } ) end diff --git a/extra/lib/plausible/installation_support/check_runner.ex b/extra/lib/plausible/installation_support/check_runner.ex index 8c267df90f..73aa5f8455 100644 --- a/extra/lib/plausible/installation_support/check_runner.ex +++ b/extra/lib/plausible/installation_support/check_runner.ex @@ -30,14 +30,14 @@ defmodule Plausible.InstallationSupport.CheckRunner do Enum.reduce_while( checks, state, - fn check, state -> + fn {check, check_opts}, state -> if state.skip_further_checks? do {:halt, state} else {:cont, state |> notify_check_start(check, slowdown) - |> check.perform_safe()} + |> check.perform_safe(check_opts)} end end ) diff --git a/extra/lib/plausible/installation_support/checks/detection.ex b/extra/lib/plausible/installation_support/checks/detection.ex index d5a3248aee..b4b7f925b3 100644 --- a/extra/lib/plausible/installation_support/checks/detection.ex +++ b/extra/lib/plausible/installation_support/checks/detection.ex @@ -63,9 +63,6 @@ defmodule Plausible.InstallationSupport.Checks.Detection do # To support browserless API being unavailable or overloaded, we retry the endpoint call if it doesn't return a successful response @max_retries 1 - @impl true - def timeout_ms, do: 6_000 - @impl true def report_progress_as, do: "We're checking your site to recommend the best installation method" diff --git a/extra/lib/plausible/installation_support/checks/verify_installation.ex b/extra/lib/plausible/installation_support/checks/verify_installation.ex index 86eda2b709..c0324d7462 100644 --- a/extra/lib/plausible/installation_support/checks/verify_installation.ex +++ b/extra/lib/plausible/installation_support/checks/verify_installation.ex @@ -85,9 +85,6 @@ defmodule Plausible.InstallationSupport.Checks.VerifyInstallation do @max_attempts 2 @timeout_between_attempts_ms 500 - @impl true - def timeout_ms, do: 20_000 - @impl true def report_progress_as, do: "We're verifying that your visitors are being counted correctly" diff --git a/extra/lib/plausible/installation_support/checks/verify_installation_cache_bust.ex b/extra/lib/plausible/installation_support/checks/verify_installation_cache_bust.ex index 9023cb472a..2826213470 100644 --- a/extra/lib/plausible/installation_support/checks/verify_installation_cache_bust.ex +++ b/extra/lib/plausible/installation_support/checks/verify_installation_cache_bust.ex @@ -15,9 +15,6 @@ defmodule Plausible.InstallationSupport.Checks.VerifyInstallationCacheBust do alias Plausible.InstallationSupport use Plausible.InstallationSupport.Check - @impl true - def timeout_ms, do: 20_000 - @impl true def report_progress_as, do: "We're verifying that your visitors are being counted correctly" diff --git a/extra/lib/plausible/installation_support/detection/checks.ex b/extra/lib/plausible/installation_support/detection/checks.ex index a078201593..1514f9a9fb 100644 --- a/extra/lib/plausible/installation_support/detection/checks.ex +++ b/extra/lib/plausible/installation_support/detection/checks.ex @@ -10,12 +10,15 @@ defmodule Plausible.InstallationSupport.Detection.Checks do require Logger - @checks [ - Checks.Url, - Checks.Detection - ] + @detection_check_timeout 6000 def run(url, data_domain, opts \\ []) do + detection_check_timeout = + case Keyword.get(opts, :detection_check_timeout) do + int when is_integer(int) -> int + _ -> @detection_check_timeout + end + report_to = Keyword.get(opts, :report_to, self()) async? = Keyword.get(opts, :async?, true) slowdown = Keyword.get(opts, :slowdown, 500) @@ -30,7 +33,12 @@ defmodule Plausible.InstallationSupport.Detection.Checks do assigns: %{detect_v1?: detect_v1?} } - CheckRunner.run(init_state, @checks, + checks = [ + {Checks.Url, []}, + {Checks.Detection, [timeout: detection_check_timeout]} + ] + + CheckRunner.run(init_state, checks, async?: async?, report_to: report_to, slowdown: slowdown diff --git a/extra/lib/plausible/installation_support/detection/diagnostics.ex b/extra/lib/plausible/installation_support/detection/diagnostics.ex index bff98fa57b..4e4b405270 100644 --- a/extra/lib/plausible/installation_support/detection/diagnostics.ex +++ b/extra/lib/plausible/installation_support/detection/diagnostics.ex @@ -65,7 +65,7 @@ defmodule Plausible.InstallationSupport.Detection.Diagnostics do end def interpret(%__MODULE__{service_error: %{code: code}}, _url) - when code in [:bad_browserless_response, :browserless_timeout] do + when code in [:bad_browserless_response, :browserless_timeout, :internal_check_timeout] do failure(:browserless_issue) end diff --git a/extra/lib/plausible/installation_support/verification/checks.ex b/extra/lib/plausible/installation_support/verification/checks.ex index 3ffd58a6b2..2a3328d21b 100644 --- a/extra/lib/plausible/installation_support/verification/checks.ex +++ b/extra/lib/plausible/installation_support/verification/checks.ex @@ -9,14 +9,17 @@ defmodule Plausible.InstallationSupport.Verification.Checks do require Logger - @checks [ - Checks.Url, - Checks.VerifyInstallation, - Checks.VerifyInstallationCacheBust - ] + @verify_installation_check_timeout 20_000 @spec run(String.t(), String.t(), String.t(), Keyword.t()) :: {:ok, pid()} | State.t() def run(url, data_domain, installation_type, opts \\ []) do + # Timeout option for testing purposes + verify_installation_check_timeout = + case Keyword.get(opts, :verify_installation_check_timeout) do + int when is_integer(int) -> int + _ -> @verify_installation_check_timeout + end + report_to = Keyword.get(opts, :report_to, self()) async? = Keyword.get(opts, :async?, true) slowdown = Keyword.get(opts, :slowdown, 500) @@ -31,7 +34,13 @@ defmodule Plausible.InstallationSupport.Verification.Checks do } } - CheckRunner.run(init_state, @checks, + checks = [ + {Checks.Url, []}, + {Checks.VerifyInstallation, [timeout: verify_installation_check_timeout]}, + {Checks.VerifyInstallationCacheBust, [timeout: verify_installation_check_timeout]} + ] + + CheckRunner.run(init_state, checks, async?: async?, report_to: report_to, slowdown: slowdown diff --git a/extra/lib/plausible/installation_support/verification/diagnostics.ex b/extra/lib/plausible/installation_support/verification/diagnostics.ex index 5ea40d0346..afe06b4012 100644 --- a/extra/lib/plausible/installation_support/verification/diagnostics.ex +++ b/extra/lib/plausible/installation_support/verification/diagnostics.ex @@ -237,7 +237,7 @@ defmodule Plausible.InstallationSupport.Verification.Diagnostics do }) def interpret(%__MODULE__{service_error: %{code: code}}, _expected_domain, _url) - when code in [:bad_browserless_response, :browserless_timeout] do + when code in [:bad_browserless_response, :browserless_timeout, :internal_check_timeout] do unhandled_error(@error_browserless_temporary, browserless_issue: true) end diff --git a/test/plausible/installation_support/check_test.exs b/test/plausible/installation_support/check_test.exs index 2142c8cbae..3de4a7364b 100644 --- a/test/plausible/installation_support/check_test.exs +++ b/test/plausible/installation_support/check_test.exs @@ -30,7 +30,7 @@ defmodule Plausible.InstallationSupport.CheckTest do {result, log} = with_log(fn -> - FaultyCheckRaise.perform_safe(state) + FaultyCheckRaise.perform_safe(state, []) end) assert log =~ @@ -64,7 +64,7 @@ defmodule Plausible.InstallationSupport.CheckTest do {result, log} = with_log(fn -> - FaultyCheckThrow.perform_safe(state) + FaultyCheckThrow.perform_safe(state, []) end) assert log =~ @@ -79,9 +79,6 @@ defmodule Plausible.InstallationSupport.CheckTest do defmodule FaultyCheckTimeout do use Plausible.InstallationSupport.Check - @impl true - def timeout_ms, do: 100 - @impl true def report_progress_as, do: "Faulty check" @@ -95,8 +92,7 @@ defmodule Plausible.InstallationSupport.CheckTest do diagnostics: %Verification.Diagnostics{} } - result = - FaultyCheckTimeout.perform_safe(state) + result = FaultyCheckTimeout.perform_safe(state, timeout: 100) assert_matches %Verification.Diagnostics{ service_error: %{ diff --git a/test/plausible/installation_support/detection/checks_observability_test.exs b/test/plausible/installation_support/detection/checks_observability_test.exs new file mode 100644 index 0000000000..39c817a1b6 --- /dev/null +++ b/test/plausible/installation_support/detection/checks_observability_test.exs @@ -0,0 +1,263 @@ +defmodule Plausible.InstallationSupport.Detection.ChecksObservabilityTest do + @moduledoc """ + Tests for capturing logs/telemetry/Sentry upon detection diagnostics interpretation. + Needs to be synchronous due to Sentry assertions, hence a separate module. + """ + use PlausibleWeb.ConnCase, async: false + + @moduletag :ee_only + + on_ee do + use Plausible.Test.Support.DNS + import ExUnit.CaptureLog + alias Plausible.InstallationSupport.Detection.Checks + + @moduletag :capture_log + + @expected_domain "example.com" + @working_url "https://#{@expected_domain}" + + setup %{test: test, test_pid: test_pid} do + :telemetry.attach_many( + "#{test}-telemetry-handler", + [ + Checks.telemetry_event_success(), + Checks.telemetry_event_failure() + ], + fn event, %{}, _, _ -> + send(test_pid, {:telemetry_event, event}) + end, + %{} + ) + + Sentry.put_config(:test_mode, true) + Sentry.put_config(:send_result, :sync) + Sentry.put_config(:dedup_events, false) + + assert :ok = Sentry.Test.start_collecting(owner: test_pid) + + on_exit(fn -> + Sentry.put_config(:test_mode, false) + Sentry.put_config(:send_result, :none) + Sentry.put_config(:dedup_events, true) + end) + end + + test "successful detection -> no logs, no sentry, telemetry :success" do + stub_lookup_a_records(@expected_domain) + + detection_stub = + json_response_detection_stub(%{ + "completed" => true, + "v1Detected" => nil, + "gtmLikely" => false, + "npm" => false, + "wordpressLikely" => true, + "wordpressPlugin" => false + }) + + state = run_checks(detection_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log == "" + + assert [] = Sentry.Test.pop_sentry_reports() + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_success() + end + + test "domain not found -> customer website issue" do + stub_lookup_a_records(@expected_domain, []) + + detection_counter = + Req.Test.stub(Plausible.InstallationSupport.Checks.Detection, fn _conn -> + raise "This check should've been skipped" + end) + + state = + Checks.run(@working_url, @expected_domain, + report_to: nil, + async?: false, + slowdown: 0 + ) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert detection_counter + + assert log =~ "[DETECTION] Failed due to an issue with the customer website" + assert log =~ "service_error: %{code: :domain_not_found}" + + assert [] = Sentry.Test.pop_sentry_reports() + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_failure() + end + + for msg <- ["Execution context destroyed", "net::ERR_CONNECTION_REFUSED"] do + test "failure due to a known :browserless_client_error (#{msg}) -> customer website issue" do + stub_lookup_a_records(@expected_domain) + + detection_stub = + json_response_detection_stub(%{ + "completed" => false, + "error" => %{"message" => unquote(msg)} + }) + + state = run_checks(detection_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[DETECTION] Failed due to an issue with the customer website" + assert log =~ "code: :browserless_client_error" + assert log =~ ~s|extra: "#{unquote(msg)}"| + + assert [] = Sentry.Test.pop_sentry_reports() + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_failure() + end + end + + test "failure due to an unknown :browserless_client_error -> unknown failure" do + stub_lookup_a_records(@expected_domain) + + detection_stub = + json_response_detection_stub(%{ + "completed" => false, + "error" => %{"message" => "something unexpected"} + }) + + state = run_checks(detection_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[DETECTION] Unknown failure" + assert log =~ "code: :browserless_client_error" + assert log =~ ~s|extra: "something unexpected"| + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "[DETECTION] Unknown failure" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_failure() + end + + test "failure hitting the catch-all interpret clause -> unknown failure" do + stub_lookup_a_records(@expected_domain) + + detection_stub = fn conn -> + Req.Test.transport_error(conn, :econnrefused) + end + + state = run_checks(detection_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[DETECTION] Unknown failure" + assert log =~ "code: :req_error" + assert log =~ ~s|extra: :econnrefused| + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "[DETECTION] Unknown failure" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_failure() + end + + test "failure due to a flaky browserless issue -> browserless issue" do + stub_lookup_a_records(@expected_domain) + + detection_stub = fn conn -> + conn + |> put_resp_content_type("text/html") + |> send_resp(400, "some error message") + end + + state = run_checks(detection_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[DETECTION] Failed due to a Browserless issue" + assert log =~ "code: :bad_browserless_response" + assert log =~ "extra: 400" + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "[DETECTION] Failed due to a Browserless issue" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_failure() + end + + test "failure due to a browserless timeout -> browserless issue" do + stub_lookup_a_records(@expected_domain) + + detection_stub = fn conn -> + Req.Test.transport_error(conn, :timeout) + end + + state = run_checks(detection_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[DETECTION] Failed due to a Browserless issue" + assert log =~ "code: :browserless_timeout" + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "[DETECTION] Failed due to a Browserless issue" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_failure() + end + + test "failure due to internal_check_timeout -> browserless issue" do + stub_lookup_a_records(@expected_domain) + + detection_stub = fn _conn -> + # times out + Process.sleep(1000) + end + + Req.Test.stub(Plausible.InstallationSupport.Checks.Detection, detection_stub) + + state = + Checks.run(@working_url, @expected_domain, + detection_check_timeout: 100, + report_to: nil, + async?: false, + slowdown: 0 + ) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[DETECTION] Failed due to a Browserless issue" + assert log =~ "code: :internal_check_timeout" + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "[DETECTION] Failed due to a Browserless issue" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_failure() + end + + defp json_response_detection_stub(js_data) do + fn conn -> + conn + |> put_resp_content_type("application/json") + |> send_resp(200, Jason.encode!(%{"data" => js_data})) + end + end + + defp run_checks(detection_stub) do + Req.Test.stub(Plausible.InstallationSupport.Checks.Detection, detection_stub) + + Checks.run(@working_url, @expected_domain, + report_to: nil, + async?: false, + slowdown: 0 + ) + end + end +end diff --git a/test/plausible/installation_support/detection/checks_test.exs b/test/plausible/installation_support/detection/checks_test.exs index 3134cf3201..8f362a6425 100644 --- a/test/plausible/installation_support/detection/checks_test.exs +++ b/test/plausible/installation_support/detection/checks_test.exs @@ -1,20 +1,17 @@ defmodule Plausible.InstallationSupport.Detection.ChecksTest do - use Plausible - use Plausible.DataCase, async: true + use PlausibleWeb.ConnCase, async: true @moduletag :ee_only on_ee do - import Plausible.AssertMatches - alias Plausible.InstallationSupport.Detection.{Checks} - alias Plausible.InstallationSupport.Result use Plausible.Test.Support.DNS - import Plug.Conn - import ExUnit.CaptureLog + import Plausible.AssertMatches + alias Plausible.InstallationSupport.Detection.Checks + alias Plausible.InstallationSupport.Result + @moduletag :capture_log @expected_domain "example.com" - @working_url "https://#{@expected_domain}" describe "running detection" do test "handles wordpress detection, retrying on 429" do @@ -89,191 +86,6 @@ defmodule Plausible.InstallationSupport.Detection.ChecksTest do end end - describe "observability" do - setup %{test: test, test_pid: test_pid} do - :telemetry.attach_many( - "#{test}-telemetry-handler", - [ - Checks.telemetry_event_success(), - Checks.telemetry_event_failure() - ], - fn event, %{}, _, _ -> - send(test_pid, {:telemetry_event, event}) - end, - %{} - ) - end - - test "successful detection -> no logs, telemetry :success" do - stub_lookup_a_records(@expected_domain) - - detection_stub = - json_response_detection_stub(%{ - "completed" => true, - "v1Detected" => nil, - "gtmLikely" => false, - "npm" => false, - "wordpressLikely" => true, - "wordpressPlugin" => false - }) - - state = run_checks(detection_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log == "" - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_success() - end - - test "domain not found -> customer website issue" do - stub_lookup_a_records(@expected_domain, []) - - detection_counter = - Req.Test.stub(Plausible.InstallationSupport.Checks.Detection, fn _conn -> - raise "This check should've been skipped" - end) - - state = - Checks.run(@working_url, @expected_domain, - report_to: nil, - async?: false, - slowdown: 0 - ) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert detection_counter - - assert log =~ "[DETECTION] Failed due to an issue with the customer website" - assert log =~ "service_error: %{code: :domain_not_found}" - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_failure() - end - - for msg <- ["Execution context destroyed", "net::ERR_CONNECTION_REFUSED"] do - test "failure due to a known :browserless_client_error (#{msg}) -> customer website issue" do - stub_lookup_a_records(@expected_domain) - - detection_stub = - json_response_detection_stub(%{ - "completed" => false, - "error" => %{"message" => unquote(msg)} - }) - - state = run_checks(detection_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log =~ "[DETECTION] Failed due to an issue with the customer website" - assert log =~ "code: :browserless_client_error" - assert log =~ ~s|extra: "#{unquote(msg)}"| - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_failure() - end - end - - test "failure due to an unknown :browserless_client_error -> unknown failure" do - stub_lookup_a_records(@expected_domain) - - detection_stub = - json_response_detection_stub(%{ - "completed" => false, - "error" => %{"message" => "something unexpected"} - }) - - state = run_checks(detection_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log =~ "[DETECTION] Unknown failure" - assert log =~ "code: :browserless_client_error" - assert log =~ ~s|extra: "something unexpected"| - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_failure() - end - - test "failure hitting the catch-all interpret clause -> unknown failure" do - stub_lookup_a_records(@expected_domain) - - detection_stub = fn conn -> - Req.Test.transport_error(conn, :econnrefused) - end - - state = run_checks(detection_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log =~ "[DETECTION] Unknown failure" - assert log =~ "code: :req_error" - assert log =~ ~s|extra: :econnrefused| - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_failure() - end - - test "failure due to a flaky browserless issue -> browserless issue" do - stub_lookup_a_records(@expected_domain) - - detection_stub = fn conn -> - conn - |> put_resp_content_type("text/html") - |> send_resp(400, "some error message") - end - - state = run_checks(detection_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log =~ "[DETECTION] Failed due to a Browserless issue" - assert log =~ "code: :bad_browserless_response" - assert log =~ "extra: 400" - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_failure() - end - - test "failure due to a browserless timeout -> browserless issue" do - stub_lookup_a_records(@expected_domain) - - detection_stub = fn conn -> - Req.Test.transport_error(conn, :timeout) - end - - state = run_checks(detection_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log =~ "[DETECTION] Failed due to a Browserless issue" - assert log =~ "code: :browserless_timeout" - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_failure() - end - end - - defp json_response_detection_stub(js_data) do - fn conn -> - conn - |> put_resp_content_type("application/json") - |> send_resp(200, Jason.encode!(%{"data" => js_data})) - end - end - - defp run_checks(detection_stub) do - Req.Test.stub(Plausible.InstallationSupport.Checks.Detection, detection_stub) - - Checks.run(@working_url, @expected_domain, - report_to: nil, - async?: false, - slowdown: 0 - ) - end - defp stub_detection_result_with_counter(handler) do counter = :atomics.new(1, []) diff --git a/test/plausible/installation_support/verification/checks_observability_test.exs b/test/plausible/installation_support/verification/checks_observability_test.exs new file mode 100644 index 0000000000..871ca05805 --- /dev/null +++ b/test/plausible/installation_support/verification/checks_observability_test.exs @@ -0,0 +1,188 @@ +defmodule Plausible.InstallationSupport.Verification.ChecksObservabilityTest do + @moduledoc """ + Tests for capturing logs/telemetry/Sentry upon verification diagnostics interpretation. + Needs to be synchronous due to Sentry assertions, hence a separate module. + """ + + use PlausibleWeb.ConnCase, async: false + + @moduletag :ee_only + + on_ee do + use Plausible.Test.Support.DNS + import ExUnit.CaptureLog + alias Plausible.InstallationSupport.Verification.{Checks} + + @moduletag :capture_log + + @expected_domain "example.com" + @url_to_verify "https://#{@expected_domain}" + + setup %{test: test, test_pid: test_pid} do + :telemetry.attach_many( + "#{test}-telemetry-handler", + [ + Checks.telemetry_event_handled(), + Checks.telemetry_event_unhandled() + ], + fn event, %{}, _, _ -> + send(test_pid, {:telemetry_event, event}) + end, + %{} + ) + + Sentry.put_config(:test_mode, true) + Sentry.put_config(:send_result, :sync) + Sentry.put_config(:dedup_events, false) + + assert :ok = Sentry.Test.start_collecting(owner: test_pid) + + on_exit(fn -> + Sentry.put_config(:test_mode, false) + Sentry.put_config(:send_result, :none) + Sentry.put_config(:dedup_events, true) + end) + end + + test "known installation issue detected is considered handled" do + wrong_domain_verification_stub = + json_response_verification_stub(%{ + "completed" => true, + "trackerIsInHtml" => true, + "plausibleIsOnWindow" => true, + "plausibleIsInitialized" => true, + "testEvent" => %{ + "normalizedBody" => %{ + "domain" => "wrong-domain.com" + }, + "responseStatus" => 200 + } + }) + + state = run_checks(wrong_domain_verification_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log == "" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_handled() + + assert [] = Sentry.Test.pop_sentry_reports() + end + + test "unhandled verification case" do + verification_stub = + json_response_verification_stub(%{ + "completed" => true, + "trackerIsInHtml" => true, + "plausibleIsOnWindow" => true, + "plausibleIsInitialized" => true, + "testEvent" => %{} + }) + + state = run_checks(verification_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[VERIFICATION] Unhandled case (data_domain='#{@expected_domain}')" + assert log =~ "test_event: %{}" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_unhandled() + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "Unhandled case for site verification" + end + + test "browserless request timing out is considered unhandled" do + verification_stub = fn conn -> Req.Test.transport_error(conn, :timeout) end + state = run_checks(verification_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[VERIFICATION] Unhandled case (data_domain='#{@expected_domain}')" + assert log =~ "service_error: %{code: :browserless_timeout}" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_unhandled() + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "Browserless failure in verification" + end + + test "flaky Browserless response is considered unhandled" do + verification_stub = fn conn -> + conn + |> put_resp_content_type("text/html") + |> send_resp(400, "some error message") + end + + state = run_checks(verification_stub) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[VERIFICATION] Unhandled case (data_domain='#{@expected_domain}')" + assert log =~ "service_error: %{code: :bad_browserless_response, extra: 400}" + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_unhandled() + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "Browserless failure in verification" + end + + test "internal_check_timeout is considered unhandled" do + verification_stub = fn _conn -> + # times out + Process.sleep(1000) + end + + stub_lookup_a_records(@expected_domain) + stub_verification_result(verification_stub) + + state = + Checks.run(@url_to_verify, @expected_domain, "manual", + verify_installation_check_timeout: 100, + report_to: nil, + async?: false, + slowdown: 0 + ) + + log = capture_log(fn -> Checks.interpret_diagnostics(state) end) + + assert log =~ "[VERIFICATION] Unhandled case (data_domain='#{@expected_domain}')" + assert log =~ "code: :internal_check_timeout" + assert log =~ ~s|extra: "VerifyInstallation timed out after 100ms"| + + assert_receive {:telemetry_event, telemetry_event} + assert telemetry_event == Checks.telemetry_event_unhandled() + + assert [sentry_event] = Sentry.Test.pop_sentry_reports() + assert sentry_event.message.formatted == "Browserless failure in verification" + end + + defp json_response_verification_stub(js_data) do + fn conn -> + conn + |> put_resp_content_type("application/json") + |> send_resp(200, Jason.encode!(%{"data" => js_data})) + end + end + + defp run_checks(verification_stub) do + stub_lookup_a_records(@expected_domain) + stub_verification_result(verification_stub) + + Checks.run(@url_to_verify, @expected_domain, "manual", + report_to: nil, + async?: false, + slowdown: 0 + ) + end + + defp stub_verification_result(f) do + Req.Test.stub(Plausible.InstallationSupport.Checks.VerifyInstallation, f) + end + end +end diff --git a/test/plausible/installation_support/verification/checks_test.exs b/test/plausible/installation_support/verification/checks_test.exs index 1267bbe459..a0b7ef39a8 100644 --- a/test/plausible/installation_support/verification/checks_test.exs +++ b/test/plausible/installation_support/verification/checks_test.exs @@ -1,16 +1,14 @@ defmodule Plausible.InstallationSupport.Verification.ChecksTest do - use Plausible - use Plausible.DataCase, async: true + use PlausibleWeb.ConnCase, async: true @moduletag :ee_only on_ee do + use Plausible.Test.Support.DNS import Plausible.AssertMatches alias Plausible.InstallationSupport.Verification.{Checks, Diagnostics} alias Plausible.InstallationSupport.Result - use Plausible.Test.Support.DNS - import Plug.Conn - import ExUnit.CaptureLog + @moduletag :capture_log @expected_domain "example.com" @@ -529,99 +527,6 @@ defmodule Plausible.InstallationSupport.Verification.ChecksTest do end end - describe "observability" do - setup %{test: test, test_pid: test_pid} do - :telemetry.attach_many( - "#{test}-telemetry-handler", - [ - Checks.telemetry_event_handled(), - Checks.telemetry_event_unhandled() - ], - fn event, %{}, _, _ -> - send(test_pid, {:telemetry_event, event}) - end, - %{} - ) - end - - test "known installation issue detected is considered handled" do - wrong_domain_verification_stub = - json_response_verification_stub(%{ - "completed" => true, - "trackerIsInHtml" => true, - "plausibleIsOnWindow" => true, - "plausibleIsInitialized" => true, - "testEvent" => %{ - "normalizedBody" => %{ - "domain" => "wrong-domain.com" - }, - "responseStatus" => 200 - } - }) - - state = run_checks(wrong_domain_verification_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log == "" - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_handled() - end - - test "unhandled verification case" do - verification_stub = - json_response_verification_stub(%{ - "completed" => true, - "trackerIsInHtml" => true, - "plausibleIsOnWindow" => true, - "plausibleIsInitialized" => true, - "testEvent" => %{} - }) - - state = run_checks(verification_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log =~ "[VERIFICATION] Unhandled case (data_domain='#{@expected_domain}')" - assert log =~ "test_event: %{}" - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_unhandled() - end - - test "browserless request timing out is considered unhandled" do - verification_stub = fn conn -> Req.Test.transport_error(conn, :timeout) end - state = run_checks(verification_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log =~ "[VERIFICATION] Unhandled case (data_domain='#{@expected_domain}')" - assert log =~ "service_error: %{code: :browserless_timeout}" - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_unhandled() - end - - test "flaky Browserless response is considered unhandled" do - verification_stub = fn conn -> - conn - |> put_resp_content_type("text/html") - |> send_resp(400, "some error message") - end - - state = run_checks(verification_stub) - - log = capture_log(fn -> Checks.interpret_diagnostics(state) end) - - assert log =~ "[VERIFICATION] Unhandled case (data_domain='#{@expected_domain}')" - assert log =~ "service_error: %{code: :bad_browserless_response, extra: 400}" - - assert_receive {:telemetry_event, telemetry_event} - assert telemetry_event == Checks.telemetry_event_unhandled() - end - end - defp json_response_verification_stub(js_data) do fn conn -> conn