fix: RealtimeChannel.Logging when a non binary message is logged (#1450)

Author: edgurgel

lib/realtime_web/channels/realtime_channel/logging.ex

@@ -19,6 +19,8 @@ defmodule RealtimeWeb.RealtimeChannel.Logging do
   def maybe_log(%{assigns: %{log_level: log_level}}, level, code, msg, metadata \\ []) do
     metadata = if metadata == [], do: Logger.metadata()
 
+    msg = stringify!(msg)
+
     if Logger.compare_levels(log_level, level) != :gt do
       Logger.log(level, "#{code}: #{msg}", metadata)
     end
@@ -86,11 +88,7 @@ defmodule RealtimeWeb.RealtimeChannel.Logging do
         msg
       ) do
     if Logger.compare_levels(log_level, :info) == :eq do
-      msg =
-        case msg do
-          msg when is_binary(msg) -> msg
-          _ -> inspect(msg, pretty: true)
-        end
+      msg = stringify!(msg)
 
       msg = "Received message on " <> channel_name <> " with payload: " <> msg
       Logger.log(log_level, msg)
@@ -99,6 +97,13 @@ defmodule RealtimeWeb.RealtimeChannel.Logging do
     socket
   end
 
+  defp stringify!(msg) do
+    case msg do
+      msg when is_binary(msg) -> msg
+      _ -> inspect(msg, pretty: true)
+    end
+  end
+
   @doc """
   List of errors that are system triggered and not user driven
   """

mix.exs

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

test/integration/rt_channel_test.exs

@@ -112,6 +112,41 @@ defmodule Realtime.Integration.RtChannelTest do
       :ok
     end
 
+    test "error subscribing", %{tenant: tenant} do
+      {:ok, conn} = Database.connect(tenant, "realtime_test")
+
+      # Let's drop the publication to cause an error
+      Database.transaction(conn, fn db_conn ->
+        Postgrex.query!(db_conn, "drop publication if exists supabase_realtime_test")
+      end)
+
+      {socket, _} = get_connection(tenant)
+      topic = "realtime:any"
+      config = %{postgres_changes: [%{event: "INSERT", schema: "public"}]}
+
+      log =
+        capture_log(fn ->
+          WebsocketClient.join(socket, topic, %{config: config})
+
+          assert_receive %Message{
+                           event: "system",
+                           payload: %{
+                             "channel" => "any",
+                             "extension" => "postgres_changes",
+                             "message" =>
+                               "{:error, \"Unable to subscribe to changes with given parameters. Please check Realtime is enabled for the given connect parameters: [event: INSERT, schema: public]\"}",
+                             "status" => "error"
+                           },
+                           ref: nil,
+                           topic: ^topic
+                         },
+                         8000
+        end)
+
+      assert log =~ "RealtimeDisabledForConfiguration"
+      assert log =~ "Unable to subscribe to changes with given parameters"
+    end
+
     test "handle insert", %{tenant: tenant} do
       {socket, _} = get_connection(tenant)
       topic = "realtime:any"

test/realtime_web/channels/realtime_channel/logging_test.exs

@@ -85,6 +85,18 @@ defmodule RealtimeWeb.RealtimeChannel.LoggingTest do
              end) =~ "TestError: test error"
     end
 
+    test "logs messages when not binary message" do
+      socket = %{assigns: %{log_level: :info}}
+
+      assert capture_log(fn ->
+               Logging.maybe_log(socket, :info, "TestCode", {:error, "Error message"})
+             end) =~ "TestCode: {:error, \"Error message\"}"
+
+      assert capture_log(fn ->
+               Logging.maybe_log(socket, :error, "TestError", "test error")
+             end) =~ "TestError: test error"
+    end
+
     test "does not log messages when log level is higher than the configured level" do
       socket = %{assigns: %{log_level: :error}}