fix: invalid JWT on join (#1498)

Author: edgurgel

lib/realtime_web/channels/realtime_channel/logging.ex

@@ -9,18 +9,25 @@ defmodule RealtimeWeb.RealtimeChannel.Logging do
   @doc """
   Logs an error message
   """
-  def log_error(socket, code, msg), do: log(socket, :error, code, msg)
+  @spec log_error(socket :: Phoenix.Socket.t(), code :: binary(), msg :: any()) ::
+          {:error, %{reason: binary}}
+  def log_error(socket, code, msg) do
+    msg = build_msg(code, msg)
+    emit_system_error(:error, code)
+    log(socket, :error, msg)
+    {:error, %{reason: msg}}
+  end
 
   @doc """
   Logs an error if the log level is set to error
   """
-  @spec maybe_log_error(socket :: Phoenix.Socket.t(), code :: binary(), msg :: any()) :: :ok
+  @spec maybe_log_error(socket :: Phoenix.Socket.t(), code :: binary(), msg :: any()) :: {:error, %{reason: binary}}
   def maybe_log_error(socket, code, msg), do: maybe_log(socket, :error, code, msg)
 
   @doc """
   Logs a warning if the log level is set to warning
   """
-  @spec maybe_log_warning(socket :: Phoenix.Socket.t(), code :: binary(), msg :: any()) :: :ok
+  @spec maybe_log_warning(socket :: Phoenix.Socket.t(), code :: binary(), msg :: any()) :: {:error, %{reason: binary}}
   def maybe_log_warning(socket, code, msg), do: maybe_log(socket, :warning, code, msg)
 
   @doc """
@@ -29,19 +36,23 @@ defmodule RealtimeWeb.RealtimeChannel.Logging do
   @spec maybe_log_info(socket :: Phoenix.Socket.t(), msg :: any()) :: :ok
   def maybe_log_info(socket, msg), do: maybe_log(socket, :info, nil, msg)
 
-  defp log(%{assigns: %{tenant: tenant, access_token: access_token}}, level, code, msg) do
+  defp build_msg(code, msg) do
+    msg = stringify!(msg)
+    if code, do: "#{code}: #{msg}", else: msg
+  end
+
+  defp log(%{assigns: %{tenant: tenant, access_token: access_token}}, level, msg) do
     Logger.metadata(external_id: tenant, project: tenant)
-    emit_system_error(level, code)
     if level in [:error, :warning], do: update_metadata_with_token_claims(access_token)
 
-    msg = stringify!(msg)
-    msg = if code, do: "#{code}: #{msg}", else: msg
     Logger.log(level, msg)
-    if level in [:error, :warning], do: {:error, %{reason: msg}}, else: :ok
   end
 
   defp maybe_log(%{assigns: %{log_level: log_level}} = socket, level, code, msg) do
-    if Logger.compare_levels(log_level, level) != :gt, do: log(socket, level, code, msg), else: :ok
+    msg = build_msg(code, msg)
+    emit_system_error(level, code)
+    if Logger.compare_levels(log_level, level) != :gt, do: log(socket, level, msg)
+    if level in [:error, :warning], do: {:error, %{reason: msg}}, else: :ok
   end
 
   @system_errors [

mix.exs

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

test/realtime_web/channels/realtime_channel/logging_test.exs

@@ -27,20 +27,28 @@ defmodule RealtimeWeb.RealtimeChannel.LoggingTest do
       for log_level <- log_levels do
         socket = %{assigns: %{log_level: log_level, tenant: random_string(), access_token: "test_token"}}
 
-        assert capture_log(fn -> Logging.maybe_log_error(socket, "TestCode", "test message") end) =~
-                 "TestCode: test message"
-
-        assert capture_log(fn -> Logging.maybe_log_error(socket, "TestCode", %{a: "b"}) end) =~
-                 "TestCode: %{a: \"b\"}"
+        assert capture_log(fn ->
+                 assert Logging.maybe_log_error(socket, "TestCode", "test message") ==
+                          {:error, %{reason: "TestCode: test message"}}
+               end) =~ "TestCode: test message"
+
+        assert capture_log(fn ->
+                 assert Logging.maybe_log_error(socket, "TestCode", %{a: "b"}) ==
+                          {:error, %{reason: "TestCode: %{a: \"b\"}"}}
+               end) =~ "TestCode: %{a: \"b\"}"
       end
     end
 
     test "does not log error message when log_level is higher than error" do
       socket = %{assigns: %{log_level: :critical, tenant: random_string(), access_token: "test_token"}}
-      assert capture_log(fn -> Logging.maybe_log_error(socket, "TestCode", "test message") end) == ""
+
+      assert capture_log(fn ->
+               assert Logging.maybe_log_error(socket, "TestCode", "test message") ==
+                        {:error, %{reason: "TestCode: test message"}}
+             end) == ""
     end
 
-    test "returns {:error, %{reason: msg}} when log_level is error" do
+    test "also returns {:error, %{reason: msg}} when log_level is error" do
       socket = %{assigns: %{log_level: :error, tenant: random_string(), access_token: "test_token"}}
 
       assert Logging.maybe_log_error(socket, "TestCode", "test message") ==
@@ -55,20 +63,29 @@ defmodule RealtimeWeb.RealtimeChannel.LoggingTest do
       for log_level <- log_levels do
         socket = %{assigns: %{log_level: log_level, tenant: random_string(), access_token: "test_token"}}
 
-        assert capture_log(fn -> Logging.maybe_log_warning(socket, "TestCode", "test message") end) =~
+        assert capture_log(fn ->
+                 assert Logging.maybe_log_warning(socket, "TestCode", "test message") ==
+                          {:error, %{reason: "TestCode: test message"}}
+               end) =~
                  "TestCode: test message"
 
-        assert capture_log(fn -> Logging.maybe_log_warning(socket, "TestCode", %{a: "b"}) end) =~
-                 "TestCode: %{a: \"b\"}"
+        assert capture_log(fn ->
+                 assert Logging.maybe_log_warning(socket, "TestCode", %{a: "b"}) ==
+                          {:error, %{reason: "TestCode: %{a: \"b\"}"}}
+               end) =~ "TestCode: %{a: \"b\"}"
       end
     end
 
     test "does not log error message when log_level is higher than warning" do
       socket = %{assigns: %{log_level: :error, tenant: random_string(), access_token: "test_token"}}
-      assert capture_log(fn -> Logging.maybe_log_warning(socket, "TestCode", "test message") end) == ""
+
+      assert capture_log(fn ->
+               assert Logging.maybe_log_warning(socket, "TestCode", "test message") ==
+                        {:error, %{reason: "TestCode: test message"}}
+             end) == ""
     end
 
-    test "returns {:error, %{reason: msg}} when log_level is warning" do
+    test "also returns {:error, %{reason: msg}} when log_level is warning" do
       socket = %{assigns: %{log_level: :warning, tenant: random_string(), access_token: "test_token"}}
 
       assert Logging.maybe_log_warning(socket, "TestCode", "test message") ==
@@ -109,11 +126,15 @@ defmodule RealtimeWeb.RealtimeChannel.LoggingTest do
     socket = %{assigns: %{log_level: :error, tenant: random_string(), access_token: "test_token"}}
 
     for error <- Logging.system_errors() do
-      Logging.maybe_log_error(socket, error, "test error")
+      assert Logging.maybe_log_error(socket, error, "test error") ==
+               {:error, %{reason: "#{error}: test error"}}
+
       assert_receive {[:realtime, :channel, :error], %{code: ^error}, %{code: ^error}}
     end
 
-    Logging.maybe_log_error(socket, "TestError", "test error")
+    assert Logging.maybe_log_error(socket, "TestError", "test error") ==
+             {:error, %{reason: "TestError: test error"}}
+
     refute_receive {[:realtime, :channel, :error], :_, :_}
   end