Extract shape_handle from logger calls into metadata, to facilitate grouping and searching

.changeset/rotten-turkeys-rhyme.md

@@ -0,0 +1,5 @@
+---
+'@core/sync-service': patch
+---
+
+Replace literal shape handles in log output with metadata. Makes it easier to search through and group log entries in observability tools.

integration-tests/tests/manual-table-publishing.lux

@@ -42,7 +42,7 @@
 
 [shell electric]
   -
-  ?\[warning\] Failed to create snapshot for \d+-\d+: Database table \"public.items\" is missing from the publication \"electric_publication_integration\" and the ELECTRIC_MANUAL_TABLE_PUBLISHING setting prevents Electric from adding it
+  ?shape_handle=\d+-\d+ .*\[warning\] Failed to create snapshot for shape: Database table \"public.items\" is missing from the publication \"electric_publication_integration\" and the ELECTRIC_MANUAL_TABLE_PUBLISHING setting prevents Electric from adding it
   -$fail_pattern
 
 ## Add the table to the publication and try again
@@ -63,7 +63,7 @@
 
 [shell electric]
   -
-  ?\[warning\] Failed to create snapshot for \d+-\d+: Database table \"public.items\" does not have its replica identity set to FULL
+  ?shape_handle=\d+-\d+ .*\[warning\] Failed to create snapshot for shape: Database table \"public.items\" does not have its replica identity set to FULL
   -$fail_pattern
 
 ## Set table's replica identity to FULL and try again

packages/sync-service/lib/electric/replication/shape_log_collector.ex

@@ -290,7 +290,8 @@ defmodule Electric.Replication.ShapeLogCollector do
 
                 {:error, {:missing_dependencies, missing_deps}} ->
                   Logger.warning(
-                    "Skipping shape #{shape_handle} during restore: missing dependencies #{inspect(MapSet.to_list(missing_deps))}"
+                    "Skipping shape during restore: missing dependencies #{inspect(MapSet.to_list(missing_deps))}",
+                    shape_handle: shape_handle
                   )
 
                   {partitions, event_router, layers, count}
@@ -412,7 +413,8 @@ defmodule Electric.Replication.ShapeLogCollector do
 
                   {:error, {:missing_dependencies, missing_deps}} ->
                     Logger.warning(
-                      "Shape #{shape_handle} cannot be added: missing dependencies #{inspect(MapSet.to_list(missing_deps))}"
+                      "Shape cannot be added: missing dependencies #{inspect(MapSet.to_list(missing_deps))}",
+                      shape_handle: shape_handle
                     )
 
                     {state, Map.put(results, shape_handle, {:error, :missing_dependencies})}

packages/sync-service/lib/electric/shape_cache.ex

@@ -154,7 +154,10 @@ defmodule Electric.ShapeCache do
             # Please note that :await_snapshot_start can also return a timeout error as well
             # as the call timing out and being handled here. A timeout error will be returned
             # by :await_snapshot_start if the PublicationManager queries take longer than 5 seconds.
-            Logger.error("Failed to await snapshot start for shape #{shape_handle}: timeout")
+            Logger.error("Failed to await snapshot start for shape: timeout",
+              shape_handle: shape_handle
+            )
+
             {:error, %RuntimeError{message: "Timed out while waiting for snapshot to start"}}
 
           :exit, {:noproc, _} ->
@@ -212,7 +215,8 @@ defmodule Electric.ShapeCache do
                 # clients that all want to fetch this shape.
 
                 Logger.warning(
-                  "Exhausted retry attempts while waiting for a shape consumer to start initial snapshot creation for #{shape_handle}"
+                  "Exhausted retry attempts while waiting for a shape consumer to start initial snapshot creation for shape",
+                  shape_handle: shape_handle
                 )
 
                 {:error, Electric.SnapshotError.slow_snapshot_start()}
@@ -432,7 +436,7 @@ defmodule Electric.ShapeCache do
         {:ok, consumer_pid}
 
       {:error, _reason} = error ->
-        Logger.error("Failed to start shape #{shape_handle}: #{inspect(error)}")
+        Logger.error("Failed to start shape: #{inspect(error)}", shape_handle: shape_handle)
         # purge because we know the consumer isn't running
         clean_shape(shape_handle, stack_id)
         :error
@@ -468,7 +472,9 @@ defmodule Electric.ShapeCache do
       {:error, failed_handle} ->
         if failed_handle != shape_handle do
           Logger.warning(
-            "Failed to start consumer for handle #{shape_handle}: error starting consumer for inner shape #{failed_handle}"
+            "Failed to start consumer for shape: error starting consumer for inner shape",
+            shape_handle: shape_handle,
+            failed_handle: failed_handle
           )
 
           # If we got an error starting any of the dependent shapes then we

packages/sync-service/lib/electric/shapes/api.ex

@@ -740,11 +740,17 @@ defmodule Electric.Shapes.Api do
 
       {:error, %SnapshotError{type: :schema_changed}} ->
         error = Api.Error.must_refetch()
-        Logger.warning("Schema changed while creating snapshot for #{shape_handle}")
+
+        Logger.warning("Schema changed while creating snapshot for shape",
+          shape_handle: shape_handle
+        )
+
         Response.error(request, error.message, status: error.status)
 
       {:error, %SnapshotError{} = error} ->
-        Logger.warning("Failed to create snapshot for #{shape_handle}: #{error.message}")
+        Logger.warning("Failed to create snapshot for shape: #{error.message}",
+          shape_handle: shape_handle
+        )
 
         if error.type == :unknown &&
              DbConnectionError.from_error(error.original_error).type == :unknown do

packages/sync-service/lib/electric/shapes/consumer.ex

@@ -358,7 +358,7 @@ defmodule Electric.Shapes.Consumer do
   end
 
   def handle_info({:materializer_shape_invalidated, shape_handle}, state) do
-    Logger.warning("Materializer shape invalidated for #{shape_handle}")
+    Logger.warning("Materializer shape invalidated for shape", shape_handle: shape_handle)
     stop_and_clean(state)
   end
 
@@ -1122,7 +1122,9 @@ defmodule Electric.Shapes.Consumer do
       else
         _ ->
           Logger.warning(
-            "Materializer for #{shape_handle} is not alive, invalidating shape #{state.shape_handle}"
+            "Materializer for shape is not alive, invalidating shape",
+            shape_handle: shape_handle,
+            state_shape_handle: state.shape_handle
           )
 
           false

packages/sync-service/lib/electric/shapes/consumer/snapshotter.ex

@@ -99,7 +99,9 @@ defmodule Electric.Shapes.Consumer.Snapshotter do
           {:stop, :normal, state}
 
         nil ->
-          Logger.error("Unable to start snapshot - consumer not found for shape #{shape_handle}")
+          Logger.error("Unable to start snapshot - consumer not found for shape",
+            shape_handle: shape_handle
+          )
 
           {:stop, {:error, "consumer not found"}, state}
       end

packages/sync-service/test/electric/shape_cache_test.exs

@@ -1168,7 +1168,7 @@ defmodule Electric.ShapeCacheTest do
 
       assert String.contains?(
                log,
-               "[warning] Exhausted retry attempts while waiting for a shape consumer to start initial snapshot creation for #{shape_handle}"
+               "shape_handle=#{shape_handle} [warning] Exhausted retry attempts while waiting for a shape consumer to start initial snapshot creation for shape"
              )
     end