fix: move invalid jwt log to warning level (#1490)

Author: filipecabaco

lib/realtime_web/channels/realtime_channel.ex

@@ -55,6 +55,9 @@ defmodule RealtimeWeb.RealtimeChannel do
       |> assign(:private?, !!params["config"]["private"])
       |> assign(:policies, nil)
 
+    token = socket.assigns.access_token
+    log_level = socket.assigns.log_level
+
     with :ok <- SignalHandler.shutdown_in_progress?(),
          :ok <- only_private?(tenant_id, socket),
          :ok <- limit_joins(socket.assigns),
@@ -118,11 +121,11 @@ defmodule RealtimeWeb.RealtimeChannel do
       {:ok, state, assign(socket, assigns)}
     else
       {:error, :expired_token, msg} ->
-        Logging.log_error_with_token_metadata("InvalidJWTToken", msg, socket.assigns.access_token)
+        Logging.maybe_log_warning_with_token_metadata("InvalidJWTToken", msg, token, log_level)
 
       {:error, :missing_claims} ->
         msg = "Fields `role` and `exp` are required in JWT"
-        Logging.log_error_with_token_metadata("InvalidJWTToken", msg, socket.assigns.access_token)
+        Logging.maybe_log_warning_with_token_metadata("InvalidJWTToken", msg, token, log_level)
 
       {:error, :unauthorized, msg} ->
         Logging.log_error_message(:error, "Unauthorized", msg)

lib/realtime_web/channels/realtime_channel/logging.ex

@@ -29,27 +29,46 @@ defmodule RealtimeWeb.RealtimeChannel.Logging do
   """
   @spec log_error_with_token_metadata(code :: binary(), msg :: binary(), token :: Joken.bearer_token()) ::
           {:error, %{reason: binary()}}
-  def log_error_with_token_metadata(code, msg, token) do
+  def log_error_with_token_metadata(code, msg, token) when is_binary(token) do
     metadata = Logger.metadata()
     metadata = update_metadata_with_token_claims(metadata, token)
     log_error_message(:error, code, msg, metadata)
   end
 
   @doc """
-  Logs an error with token metadata
+  Logs a warning with token metadata
   """
   @spec log_warning_with_token_metadata(
           code :: binary(),
           msg :: binary(),
           token :: Joken.bearer_token(),
           metadata :: keyword()
         ) :: {:error, %{reason: binary()}}
-  def log_warning_with_token_metadata(code, msg, token, metadata \\ []) do
-    if metadata == [], do: Logger.metadata()
+
+  def log_warning_with_token_metadata(code, msg, token, metadata \\ []) when is_binary(token) do
+    metadata = if metadata == [], do: Logger.metadata(), else: metadata
     metadata = update_metadata_with_token_claims(metadata, token)
     log_error_message(:warning, code, msg, metadata)
   end
 
+  @doc """
+  Maybe logs a warning with token metadata if the log level is set to warning
+  """
+  @spec maybe_log_warning_with_token_metadata(
+          code :: binary(),
+          msg :: binary(),
+          token :: Joken.bearer_token(),
+          log_level :: Logger.level()
+        ) :: {:error, %{reason: binary()}}
+
+  def maybe_log_warning_with_token_metadata(code, msg, token, log_level) when is_binary(token) do
+    if Logger.compare_levels(log_level, :warning) != :gt do
+      log_warning_with_token_metadata(code, msg, token)
+    end
+
+    {:error, %{reason: msg}}
+  end
+
   defp update_metadata_with_token_claims(metadata, token) do
     case Joken.peek_claims(token) do
       {:ok, claims} ->

lib/realtime_web/channels/user_socket.ex

@@ -28,10 +28,11 @@ defmodule RealtimeWeb.UserSocket do
       %{uri: %{host: host}, x_headers: headers} = opts
 
       {:ok, external_id} = Database.get_external_id(host)
-      Logger.metadata(external_id: external_id, project: external_id)
-      Logger.put_process_level(self(), :error)
-
       token = access_token(params, headers)
+      log_level = log_level(params)
+
+      Logger.metadata(external_id: external_id, project: external_id)
+      Logger.put_process_level(self(), log_level)
 
       with %Tenant{
              jwt_secret: jwt_secret,
@@ -67,7 +68,7 @@ defmodule RealtimeWeb.UserSocket do
           postgres_extension: PostgresCdc.filter_settings(postgres_cdc_default, extensions),
           postgres_cdc_module: postgres_cdc_module,
           tenant: external_id,
-          log_level: log_level(params),
+          log_level: log_level,
           tenant_token: token,
           headers: opts.x_headers
         }
@@ -85,11 +86,12 @@ defmodule RealtimeWeb.UserSocket do
           {:error, :tenant_suspended}
 
         {:error, :expired_token, msg} ->
-          Logging.log_error_with_token_metadata("InvalidJWTToken", msg, token)
+          Logging.maybe_log_warning_with_token_metadata("InvalidJWTToken", msg, token, log_level)
           {:error, :expired_token}
 
         {:error, :missing_claims} ->
-          Logging.log_error_with_token_metadata("InvalidJWTToken", "Fields `role` and `exp` are required in JWT", token)
+          msg = "Fields `role` and `exp` are required in JWT"
+          Logging.maybe_log_warning_with_token_metadata("InvalidJWTToken", msg, token, log_level)
           {:error, :missing_claims}
 
         {:error, :token_malformed} ->

mix.exs

@@ -4,7 +4,7 @@ defmodule Realtime.MixProject do
   def project do
     [
       app: :realtime,
-      version: "2.41.19",
+      version: "2.41.20",
       elixir: "~> 1.17.3",
       elixirc_paths: elixirc_paths(Mix.env()),
       start_permanent: Mix.env() == :prod,

test/integration/rt_channel_test.exs

@@ -927,7 +927,9 @@ defmodule Realtime.Integration.RtChannelTest do
 
     test "invalid JWT with expired token", %{tenant: tenant} do
       log =
-        capture_log(fn -> get_connection(tenant, "authenticated", %{:exp => System.system_time(:second) - 1000}) end)
+        capture_log(fn ->
+          get_connection(tenant, "authenticated", %{:exp => System.system_time(:second) - 1000}, %{log_level: :info})
+        end)
 
       assert log =~ "InvalidJWTToken: Token has expired"
     end
@@ -1687,7 +1689,9 @@ defmodule Realtime.Integration.RtChannelTest do
 
     test "invalid JWT with expired token", %{tenant: tenant} do
       log =
-        capture_log(fn -> get_connection(tenant, "authenticated", %{:exp => System.system_time(:second) - 1000}) end)
+        capture_log(fn ->
+          get_connection(tenant, "authenticated", %{:exp => System.system_time(:second) - 1000}, %{log_level: :info})
+        end)
 
       assert log =~ "InvalidJWTToken: Token has expired"
     end

test/realtime_web/channels/realtime_channel/logging_test.exs

@@ -10,11 +10,14 @@ defmodule RealtimeWeb.RealtimeChannel.LoggingTest do
     :telemetry.attach(__MODULE__, [:realtime, :channel, :error], &__MODULE__.handle_telemetry/4, pid: self())
     level = Logger.level()
     Logger.configure(level: :info)
+    tenant = tenant_fixture()
 
     on_exit(fn ->
       :telemetry.detach(__MODULE__)
       Logger.configure(level: level)
     end)
+
+    %{tenant: tenant}
   end
 
   describe "maybe_log_handle_info/2" do
@@ -178,11 +181,6 @@ defmodule RealtimeWeb.RealtimeChannel.LoggingTest do
   end
 
   describe "log_error_with_token_metadata/4" do
-    setup do
-      tenant = tenant_fixture()
-      %{tenant: tenant}
-    end
-
     test "logs error messages with token metadata", %{tenant: tenant} do
       sub = random_string()
       iss = "https://#{random_string()}.com"
@@ -198,22 +196,62 @@ defmodule RealtimeWeb.RealtimeChannel.LoggingTest do
   end
 
   describe "log_warning_with_token_metadata/4" do
-    setup do
-      tenant = tenant_fixture()
-      %{tenant: tenant}
+    test "logs warning messages with token metadata", %{tenant: tenant} do
+      sub = random_string()
+      iss = "https://#{random_string()}.com"
+      exp = System.system_time(:second) + 1000
+
+      token = generate_jwt_token(tenant, %{sub: sub, exp: exp, iss: iss})
+      log = capture_log(fn -> Logging.log_warning_with_token_metadata("TestCode", "test message", token) end)
+      assert log =~ "TestCode: test message"
+      assert log =~ "sub=#{sub}"
+      assert log =~ "exp=#{exp}"
+      assert log =~ "iss=#{iss}"
     end
+  end
 
+  describe "maybe_log_warning_with_token_metadata/4" do
     test "logs warning messages with token metadata", %{tenant: tenant} do
       sub = random_string()
       iss = "https://#{random_string()}.com"
       exp = System.system_time(:second) + 1000
 
       token = generate_jwt_token(tenant, %{sub: sub, exp: exp, iss: iss})
-      log = capture_log(fn -> Logging.log_warning_with_token_metadata("TestCode", "test message", token) end)
+
+      log =
+        capture_log(fn -> Logging.maybe_log_warning_with_token_metadata("TestCode", "test message", token, :warning) end)
+
       assert log =~ "TestCode: test message"
       assert log =~ "sub=#{sub}"
       assert log =~ "exp=#{exp}"
       assert log =~ "iss=#{iss}"
     end
+
+    test "logs warning messages with token metadata when log level is lower than warning", %{tenant: tenant} do
+      sub = random_string()
+      iss = "https://#{random_string()}.com"
+      exp = System.system_time(:second) + 1000
+
+      token = generate_jwt_token(tenant, %{sub: sub, exp: exp, iss: iss})
+
+      log =
+        capture_log(fn -> Logging.maybe_log_warning_with_token_metadata("TestCode", "test message", token, :info) end)
+
+      assert log =~ "TestCode: test message"
+      assert log =~ "sub=#{sub}"
+      assert log =~ "exp=#{exp}"
+      assert log =~ "iss=#{iss}"
+    end
+
+    test "does not log warning messages when log level is higher than warning" do
+      token = random_string()
+
+      log =
+        capture_log(fn ->
+          Logging.maybe_log_warning_with_token_metadata("TestCode", "test message", token, :error)
+        end)
+
+      assert log == ""
+    end
   end
 end