From f1139d0ec40b6b41dedb1bca857d70c8ff4d0cec Mon Sep 17 00:00:00 2001
From: shibao <shibao@bubbletea.dev>
Date: Sat, 4 Feb 2023 20:47:47 -0500
Subject: [PATCH] improve oban logging

---
 config/dev.exs              |  5 ++--
 lib/lokal/application.ex    | 21 ++++++++++----
 lib/lokal/error_reporter.ex | 57 +++++++++++++++++++++++++++++++++++++
 lib/lokal/repo/migrator.ex  |  7 +++--
 lib/lokal_web/telemetry.ex  | 24 ++++++++++++++++
 5 files changed, 104 insertions(+), 10 deletions(-)
 create mode 100644 lib/lokal/error_reporter.ex

diff --git a/config/dev.exs b/config/dev.exs
index e454a92..0a42474 100644
--- a/config/dev.exs
+++ b/config/dev.exs
@@ -64,8 +64,9 @@ config :lokal, LokalWeb.Endpoint,
     ]
   ]
 
-# Do not include metadata nor timestamps in development logs
-config :logger, :console, format: "[$level] $message\n"
+config :logger, :console,
+  format: "[$level] $message $metadata\n\n",
+  metadata: [:data]
 
 # Set a higher stacktrace during development. Avoid configuring such
 # in production as building large stacktraces may be expensive.
diff --git a/lib/lokal/application.ex b/lib/lokal/application.ex
index e6266a5..e63bdbd 100644
--- a/lib/lokal/application.ex
+++ b/lib/lokal/application.ex
@@ -4,6 +4,7 @@ defmodule Lokal.Application do
   @moduledoc false
 
   use Application
+  alias Lokal.ErrorReporter
 
   @impl true
   def start(_type, _args) do
@@ -17,16 +18,24 @@ defmodule Lokal.Application do
       # Start the Endpoint (http/https)
       LokalWeb.Endpoint,
       # Add Oban
-      {Oban, oban_config()}
+      {Oban, oban_config()},
+      Lokal.Repo.Migrator
       # Start a worker by calling: Lokal.Worker.start_link(arg)
       # {Lokal.Worker, arg}
     ]
 
-    # Automatically migrate on start in prod
-    children =
-      if Application.get_env(:lokal, Lokal.Application, automigrate: false)[:automigrate],
-        do: children ++ [Lokal.Repo.Migrator],
-        else: children
+    # Oban events logging https://hexdocs.pm/oban/Oban.html#module-reporting-errors
+    :ok =
+      :telemetry.attach_many(
+        "oban-logger",
+        [
+          [:oban, :job, :exception],
+          [:oban, :job, :start],
+          [:oban, :job, :stop]
+        ],
+        &ErrorReporter.handle_event/4,
+        []
+      )
 
     # See https://hexdocs.pm/elixir/Supervisor.html
     # for other strategies and supported options
diff --git a/lib/lokal/error_reporter.ex b/lib/lokal/error_reporter.ex
new file mode 100644
index 0000000..d46c555
--- /dev/null
+++ b/lib/lokal/error_reporter.ex
@@ -0,0 +1,57 @@
+defmodule Lokal.ErrorReporter do
+  @moduledoc """
+  Custom logger for telemetry events
+
+  Oban implementation taken from
+  https://hexdocs.pm/oban/Oban.html#module-reporting-errors
+  """
+
+  require Logger
+
+  def handle_event([:oban, :job, :exception], measure, %{stacktrace: stacktrace} = meta, _config) do
+    data =
+      get_oban_job_data(meta, measure)
+      |> Map.put(:stacktrace, Exception.format_stacktrace(stacktrace))
+
+    Logger.error(meta.reason, data: pretty_encode(data))
+  end
+
+  def handle_event([:oban, :job, :start], measure, meta, _config) do
+    Logger.info("Started oban job", data: get_oban_job_data(meta, measure) |> pretty_encode())
+  end
+
+  def handle_event([:oban, :job, :stop], measure, meta, _config) do
+    Logger.info("Finished oban job", data: get_oban_job_data(meta, measure) |> pretty_encode())
+  end
+
+  def handle_event([:oban, :job, unhandled_event], measure, meta, _config) do
+    data =
+      get_oban_job_data(meta, measure)
+      |> Map.put(:event, unhandled_event)
+
+    Logger.warning("Unhandled oban job event", data: pretty_encode(data))
+  end
+
+  def handle_event(unhandled_event, measure, meta, config) do
+    data = %{
+      event: unhandled_event,
+      meta: meta,
+      measurements: measure,
+      config: config
+    }
+
+    Logger.warning("Unhandled telemetry event", data: pretty_encode(data))
+  end
+
+  defp get_oban_job_data(%{job: job}, measure) do
+    job
+    |> Map.take([:id, :args, :meta, :queue, :worker])
+    |> Map.merge(measure)
+  end
+
+  defp pretty_encode(data) do
+    data
+    |> Jason.encode!()
+    |> Jason.Formatter.pretty_print()
+  end
+end
diff --git a/lib/lokal/repo/migrator.ex b/lib/lokal/repo/migrator.ex
index 2c5ba30..b1892c8 100644
--- a/lib/lokal/repo/migrator.ex
+++ b/lib/lokal/repo/migrator.ex
@@ -11,12 +11,15 @@ defmodule Lokal.Repo.Migrator do
   end
 
   def init(_opts) do
-    migrate!()
-    {:ok, nil}
+    {:ok, if(automigrate_enabled?(), do: migrate!())}
   end
 
   def migrate! do
     path = Application.app_dir(:lokal, "priv/repo/migrations")
     Ecto.Migrator.run(Lokal.Repo, path, :up, all: true)
   end
+
+  defp automigrate_enabled? do
+    Application.get_env(:lokal, Lokal.Application, automigrate: false)[:automigrate]
+  end
 end
diff --git a/lib/lokal_web/telemetry.ex b/lib/lokal_web/telemetry.ex
index 581b7fe..1966629 100644
--- a/lib/lokal_web/telemetry.ex
+++ b/lib/lokal_web/telemetry.ex
@@ -57,6 +57,30 @@ defmodule LokalWeb.Telemetry do
           "The time the connection spent waiting before being checked out for the query"
       ),
 
+      # Oban Metrics
+      counter("oban.job.exception",
+        tags: [:queue, :worker],
+        event_name: [:oban, :job, :exception],
+        measurement: :duration,
+        description: "Number of oban jobs that raised an exception"
+      ),
+      counter("oban.job.start",
+        tags: [:queue, :worker],
+        event_name: [:oban, :job, :start],
+        measurement: :system_time,
+        description: "Number of oban jobs started"
+      ),
+      summary("oban.job.stop.duration",
+        tags: [:queue, :worker],
+        unit: {:native, :millisecond},
+        description: "Length of time spent processing the oban job"
+      ),
+      summary("oban.job.stop.queue_time",
+        tags: [:queue, :worker],
+        unit: {:native, :millisecond},
+        description: "Time the oban job spent waiting in milliseconds"
+      ),
+
       # VM Metrics
       summary("vm.memory.total", unit: {:byte, :kilobyte}),
       summary("vm.total_run_queue_lengths.total"),