towerops/test/towerops_web/telemetry_test.exs

defmodule ToweropsWeb.TelemetryTest do
  # Not async: this module mutates the global Logger primary level in
  # the handle_endpoint_stop describe block, which races with other
  # async tests that adjust Logger configuration. Running it sync makes
  # the captured-log assertions deterministic.
  use ExUnit.Case, async: false

  import ExUnit.CaptureLog

  alias ToweropsWeb.Telemetry

  describe "parse_redis_info/1" do
    test "parses a minimal Redis INFO response" do
      info = """
      # Stats
      total_connections_received:12
      total_commands_processed:500
      instantaneous_ops_per_sec:5
      """

      result = Telemetry.parse_redis_info(info)
      assert result["total_connections_received"] == "12"
      assert result["total_commands_processed"] == "500"
      assert result["instantaneous_ops_per_sec"] == "5"
    end

    test "skips comment/empty lines" do
      info = "\n# Comment\n\nkey:value\n# Another\n"
      assert %{"key" => "value"} == Telemetry.parse_redis_info(info)
    end

    test "returns empty map for empty input" do
      assert %{} == Telemetry.parse_redis_info("")
    end

    test "handles CRLF line endings" do
      info = "a:1\r\nb:2\r\n"
      assert %{"a" => "1", "b" => "2"} == Telemetry.parse_redis_info(info)
    end

    test "splits on first colon only" do
      info = "url:redis://localhost:6379"
      assert %{"url" => "redis://localhost:6379"} == Telemetry.parse_redis_info(info)
    end

    test "drops malformed entries without colon" do
      info = "valid:1\njunk_no_colon\nanother:2"
      assert %{"valid" => "1", "another" => "2"} == Telemetry.parse_redis_info(info)
    end
  end

  describe "metrics/0" do
    test "returns a list of metric specs" do
      metrics = Telemetry.metrics()
      assert hd(metrics)
      refute Enum.empty?(metrics)
    end
  end

  describe "handle_router_exception/4" do
    test "logs an error with exception metadata" do
      conn = %Plug.Conn{
        method: "GET",
        request_path: "/api/devices",
        assigns: %{request_id: "req-123"}
      }

      metadata = %{
        conn: conn,
        kind: :error,
        reason: "something went wrong",
        stacktrace: [],
        plug: MyTestPlug
      }

      log =
        capture_log(fn ->
          Telemetry.handle_router_exception(:event, %{}, metadata, nil)
        end)

      assert log =~ "Router exception on Elixir.MyTestPlug GET /api/devices"
      assert log =~ "[error]"
    end
  end

  describe "handle_endpoint_stop/4" do
    setup do
      previous = Logger.level()
      Logger.configure(level: :warning)
      on_exit(fn -> Logger.configure(level: previous) end)
      :ok
    end

    test "logs warning for slow requests over 5 seconds" do
      conn = %Plug.Conn{
        method: "POST",
        request_path: "/slow-endpoint",
        status: 200,
        assigns: %{}
      }

      # Duration > 5000ms in native units
      duration_native = System.convert_time_unit(6_000, :millisecond, :native)

      log =
        capture_log(fn ->
          Telemetry.handle_endpoint_stop(
            :stop,
            %{duration: duration_native},
            %{conn: conn},
            nil
          )
        end)

      assert log =~ "Slow request: POST /slow-endpoint"
      assert log =~ "6000ms"
      assert log =~ "[warning]"
    end

    test "logs error for 5xx status codes" do
      conn = %Plug.Conn{
        method: "GET",
        request_path: "/api/broken",
        status: 500,
        assigns: %{request_id: "req-456"}
      }

      duration_native = System.convert_time_unit(100, :millisecond, :native)

      log =
        capture_log(fn ->
          Telemetry.handle_endpoint_stop(
            :stop,
            %{duration: duration_native},
            %{conn: conn},
            nil
          )
        end)

      assert log =~ "Server error: GET /api/broken returned 500"
      assert log =~ "[error]"
    end

    test "does not log for fast 2xx requests" do
      conn = %Plug.Conn{
        method: "GET",
        request_path: "/fast-endpoint",
        status: 200,
        assigns: %{}
      }

      duration_native = System.convert_time_unit(50, :millisecond, :native)

      log =
        capture_log(fn ->
          Telemetry.handle_endpoint_stop(
            :stop,
            %{duration: duration_native},
            %{conn: conn},
            nil
          )
        end)

      # capture_log catches every log line emitted by *any* process while the
      # function runs, so a stray DB sandbox or Postgrex disconnect log from
      # a concurrent test can show up here. Assert on what this function
      # itself does NOT log instead of demanding empty output.
      refute log =~ "Slow request"
      refute log =~ "Server error"
      refute log =~ "/fast-endpoint"
    end

    test "logs both warning and error for slow 5xx request" do
      conn = %Plug.Conn{
        method: "DELETE",
        request_path: "/api/resource",
        status: 503,
        assigns: %{request_id: "req-789"}
      }

      duration_native = System.convert_time_unit(7_000, :millisecond, :native)

      log =
        capture_log(fn ->
          Telemetry.handle_endpoint_stop(
            :stop,
            %{duration: duration_native},
            %{conn: conn},
            nil
          )
        end)

      assert log =~ "Slow request: DELETE /api/resource"
      assert log =~ "Server error: DELETE /api/resource returned 503"
    end

    test "does not log for fast 4xx requests" do
      conn = %Plug.Conn{
        method: "GET",
        request_path: "/not-found",
        status: 404,
        assigns: %{}
      }

      duration_native = System.convert_time_unit(100, :millisecond, :native)

      log =
        capture_log(fn ->
          Telemetry.handle_endpoint_stop(
            :stop,
            %{duration: duration_native},
            %{conn: conn},
            nil
          )
        end)

      refute log =~ "Slow request"
      refute log =~ "Server error"
      refute log =~ "/not-found"
    end
  end

  describe "publish_oban_stats/0 / publish_redis_stats/0" do
    test "are no-ops in test env" do
      assert :ok == Telemetry.publish_oban_stats()
      assert :ok == Telemetry.publish_redis_stats()
    end
  end
end