Merge pull request #27 from cheerfulstoic/debug-logs

feat: Add debug logging option

guides/introduction/Debugging.md

@@ -0,0 +1,37 @@
+It is possible to get debug logs from EctoWatch by setting the `debug?` option, either globally:
+
+```elixir
+  # setup
+  {EctoWatch,
+   repo: MyApp.Repo,
+   pub_sub: MyApp.PubSub,
+   debug?: true
+   watchers: [
+     # ...
+     {Comment, :deleted, extra_columns: [:post_id]},
+     # ...
+   ]}
+```
+
+Or on specific watchers:
+
+```elixir
+  # setup
+  {EctoWatch,
+   repo: MyApp.Repo,
+   pub_sub: MyApp.PubSub,
+   watchers: [
+     # ...
+     {Comment, :deleted, debug?: true, extra_columns: [:post_id]},
+     # ...
+   ]}
+```
+
+Debug logs will be written to the `:debug` log level.  They will output when:
+
+ * A watcher server is starting up
+ * A watcher server receives a message from PostgreSQL via a `pg_notify` channel
+ * A watcher server broadcasts a message to `Phoenix.PubSub`
+ * A process subscribes to a watcher
+
+All debug logs have a PID associated as well as the identifier for the watcher server (either the label or a `{ecto_schema, update_type}` tuple).

lib/ecto_watch.ex

@@ -147,8 +147,10 @@ defmodule EctoWatch do
     validate_ecto_watch_running!()
 
     with :ok <- validate_identifier(watcher_identifier),
-         {:ok, {pub_sub_mod, channel_name}} <-
+         {:ok, {pub_sub_mod, channel_name, debug?}} <-
            WatcherServer.pub_sub_subscription_details(watcher_identifier, id) do
+      if(debug?, do: debug_log(watcher_identifier, "Subscribing to watcher"))
+
       Phoenix.PubSub.subscribe(pub_sub_mod, channel_name)
     else
       {:error, error} ->
@@ -291,4 +293,8 @@ defmodule EctoWatch do
     |> Enum.filter(fn {_, values} -> length(values) >= 2 end)
     |> Enum.map(fn {_, [value | _]} -> value end)
   end
+
+  defp debug_log(watcher_identifier, message) do
+    EctoWatch.Helpers.debug_log(watcher_identifier, message)
+  end
 end

lib/ecto_watch/helpers.ex

@@ -1,6 +1,8 @@
 defmodule EctoWatch.Helpers do
   @moduledoc false
 
+  require Logger
+
   def label(schema_mod_or_label) do
     if ecto_schema_mod?(schema_mod_or_label) do
       module_to_label(schema_mod_or_label)
@@ -39,4 +41,8 @@ defmodule EctoWatch.Helpers do
   def validate_list(_, _) do
     {:error, "should be a list"}
   end
+
+  def debug_log(watcher_identifier, message) do
+    Logger.debug("EctoWatch | #{inspect(watcher_identifier)} | #{inspect(self())} | #{message}")
+  end
 end

lib/ecto_watch/options.ex

@@ -3,13 +3,16 @@ defmodule EctoWatch.Options do
 
   alias EctoWatch.Options.WatcherOptions
 
-  defstruct [:repo_mod, :pub_sub_mod, :watchers]
+  defstruct [:repo_mod, :pub_sub_mod, :watchers, :debug?]
 
   def new(opts) do
     %__MODULE__{
       repo_mod: opts[:repo],
       pub_sub_mod: opts[:pub_sub],
-      watchers: Enum.map(opts[:watchers], &WatcherOptions.new/1)
+      watchers:
+        Enum.map(opts[:watchers], fn watcher_opts ->
+          WatcherOptions.new(watcher_opts, opts[:debug?])
+        end)
     }
   end
 
@@ -26,6 +29,11 @@ defmodule EctoWatch.Options do
       watchers: [
         type: {:custom, WatcherOptions, :validate_list, []},
         required: true
+      ],
+      debug?: [
+        type: :boolean,
+        required: false,
+        default: false
       ]
     ]
 

lib/ecto_watch/options/watcher_options.ex

@@ -3,7 +3,7 @@ defmodule EctoWatch.Options.WatcherOptions do
 
   alias EctoWatch.Helpers
 
-  defstruct [:schema_definition, :update_type, :label, :trigger_columns, :extra_columns]
+  defstruct [:schema_definition, :update_type, :label, :trigger_columns, :extra_columns, :debug?]
 
   def validate_list(list) do
     Helpers.validate_list(list, &validate/1)
@@ -157,6 +157,11 @@ defmodule EctoWatch.Options.WatcherOptions do
         type: {:custom, __MODULE__, :validate_columns, [schema_definition]},
         required: false,
         default: []
+      ],
+      debug?: [
+        type: :boolean,
+        required: false,
+        default: false
       ]
     ]
 
@@ -198,19 +203,20 @@ defmodule EctoWatch.Options.WatcherOptions do
     end)
   end
 
-  def new({schema_definition, update_type}) do
-    new({schema_definition, update_type, []})
+  def new({schema_definition, update_type}, debug?) do
+    new({schema_definition, update_type, []}, debug?)
   end
 
-  def new({schema_definition, update_type, opts}) do
+  def new({schema_definition, update_type, opts}, debug?) do
     schema_definition = SchemaDefinition.new(schema_definition)
 
     %__MODULE__{
       schema_definition: schema_definition,
       update_type: update_type,
       label: opts[:label],
       trigger_columns: opts[:trigger_columns] || [],
-      extra_columns: opts[:extra_columns] || []
+      extra_columns: opts[:extra_columns] || [],
+      debug?: debug? || opts[:debug?]
     }
   end
 end

lib/ecto_watch/watcher_server.ex

@@ -45,6 +45,8 @@ defmodule EctoWatch.WatcherServer do
 
   @impl true
   def init({repo_mod, pub_sub_mod, options}) do
+    debug_log(options, "Starting server")
+
     unique_label = "#{unique_label(options)}"
 
     update_keyword =
@@ -152,7 +154,7 @@ defmodule EctoWatch.WatcherServer do
             "#{state.unique_label}"
           end
 
-        {:ok, {state.pub_sub_mod, channel_name}}
+        {:ok, {state.pub_sub_mod, channel_name, state.options.debug?}}
       end
 
     {:reply, result, state}
@@ -182,6 +184,11 @@ defmodule EctoWatch.WatcherServer do
 
   @impl true
   def handle_info({:notification, _pid, _ref, channel_name, payload}, state) do
+    debug_log(
+      state.options,
+      "Received Postgrex notification on channel `#{channel_name}`: #{payload}"
+    )
+
     details = watcher_details(state)
 
     if channel_name != details.notify_channel do
@@ -210,6 +217,11 @@ defmodule EctoWatch.WatcherServer do
             returned_values,
             state.identifier_columns
           ) do
+      debug_log(
+        state.options,
+        "Broadcasting to Phoenix PubSub topic `#{topic}`: #{inspect(message)}"
+      )
+
       Phoenix.PubSub.broadcast(state.pub_sub_mod, topic, message)
     end
 
@@ -244,11 +256,9 @@ defmodule EctoWatch.WatcherServer do
   # that can be used as the watcher process name, trigger name, trigger function name,
   # and Phoenix.PubSub channel name.
   defp unique_label(%WatcherOptions{} = options) do
-    if options.label do
-      unique_label(options.label)
-    else
-      unique_label({options.schema_definition.label, options.update_type})
-    end
+    options
+    |> identifier()
+    |> unique_label()
   end
 
   defp unique_label({schema_mod, update_type}) do
@@ -258,4 +268,18 @@ defmodule EctoWatch.WatcherServer do
   defp unique_label(label) do
     :"ew_for_#{Helpers.label(label)}"
   end
+
+  defp identifier(%WatcherOptions{} = options) do
+    if options.label do
+      options.label
+    else
+      {options.schema_definition.label, options.update_type}
+    end
+  end
+
+  defp debug_log(%{debug?: debug_value} = options, message) do
+    if debug_value do
+      Helpers.debug_log(identifier(options), message)
+    end
+  end
 end

mix.exs

@@ -69,6 +69,7 @@ defmodule EctoWatch.MixProject do
       "guides/introduction/Tracking columns and using labels.md",
       "guides/introduction/Getting additional values.md",
       "guides/introduction/Watching without a schema.md",
+      "guides/introduction/Debugging.md",
       "guides/introduction/Notes.md",
       "guides/howtos/Upgrading Versions.md",
       "guides/other/Potental TODOs.md",