diff --git a/.changeset/rotten-turkeys-rhyme.md b/.changeset/rotten-turkeys-rhyme.md new file mode 100644 index 0000000000..f30264ec5b --- /dev/null +++ b/.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. diff --git a/integration-tests/tests/manual-table-publishing.lux b/integration-tests/tests/manual-table-publishing.lux index 61fa4c89de..f09397d215 100644 --- a/integration-tests/tests/manual-table-publishing.lux +++ b/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 diff --git a/packages/sync-service/lib/electric/replication/shape_log_collector.ex b/packages/sync-service/lib/electric/replication/shape_log_collector.ex index 754f3e077f..4f6a30a231 100644 --- a/packages/sync-service/lib/electric/replication/shape_log_collector.ex +++ b/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})} diff --git a/packages/sync-service/lib/electric/shape_cache.ex b/packages/sync-service/lib/electric/shape_cache.ex index 6d37a61d2b..8cb52a56cd 100644 --- a/packages/sync-service/lib/electric/shape_cache.ex +++ b/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 diff --git a/packages/sync-service/lib/electric/shapes/api.ex b/packages/sync-service/lib/electric/shapes/api.ex index fad3380f9d..74f0144da3 100644 --- a/packages/sync-service/lib/electric/shapes/api.ex +++ b/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 diff --git a/packages/sync-service/lib/electric/shapes/consumer.ex b/packages/sync-service/lib/electric/shapes/consumer.ex index 027777d116..c00721e323 100644 --- a/packages/sync-service/lib/electric/shapes/consumer.ex +++ b/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 diff --git a/packages/sync-service/lib/electric/shapes/consumer/snapshotter.ex b/packages/sync-service/lib/electric/shapes/consumer/snapshotter.ex index 4a4e43b220..8ff3aa14be 100644 --- a/packages/sync-service/lib/electric/shapes/consumer/snapshotter.ex +++ b/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 diff --git a/packages/sync-service/test/electric/shape_cache_test.exs b/packages/sync-service/test/electric/shape_cache_test.exs index 77091bb28b..262210a0eb 100644 --- a/packages/sync-service/test/electric/shape_cache_test.exs +++ b/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