From 311579efd6b720ae48b2bb0ec4ccd62116b3462b Mon Sep 17 00:00:00 2001 From: shibao Date: Sat, 4 Feb 2023 20:48:17 -0500 Subject: [PATCH] improve oban logging --- changelog.md | 1 + config/dev.exs | 5 ++-- lib/memex/application.ex | 21 ++++++++++---- lib/memex/error_reporter.ex | 57 +++++++++++++++++++++++++++++++++++++ lib/memex/repo/migrator.ex | 11 ++++--- lib/memex_web/telemetry.ex | 24 ++++++++++++++++ 6 files changed, 107 insertions(+), 12 deletions(-) create mode 100644 lib/memex/error_reporter.ex diff --git a/changelog.md b/changelog.md index 5c1fae7..b70e221 100644 --- a/changelog.md +++ b/changelog.md @@ -3,6 +3,7 @@ - Improve templates - Improve invites, record usage - Fix padding on more pages when using chrome +- Add oban metrics to server log and live dashboard # v0.1.7 - Update dependencies diff --git a/config/dev.exs b/config/dev.exs index 8b325c0..5d8d90d 100644 --- a/config/dev.exs +++ b/config/dev.exs @@ -64,8 +64,9 @@ config :memex, MemexWeb.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/memex/application.ex b/lib/memex/application.ex index 2cd79c5..136742b 100644 --- a/lib/memex/application.ex +++ b/lib/memex/application.ex @@ -4,6 +4,7 @@ defmodule Memex.Application do @moduledoc false use Application + alias Memex.ErrorReporter @impl true def start(_type, _args) do @@ -17,16 +18,24 @@ defmodule Memex.Application do # Start the Endpoint (http/https) MemexWeb.Endpoint, # Add Oban - {Oban, oban_config()} + {Oban, oban_config()}, + Memex.Repo.Migrator # Start a worker by calling: Memex.Worker.start_link(arg) # {Memex.Worker, arg} ] - # Automatically migrate on start in prod - children = - if Application.get_env(:memex, Memex.Application, automigrate: false)[:automigrate], - do: children ++ [Memex.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/memex/error_reporter.ex b/lib/memex/error_reporter.ex new file mode 100644 index 0000000..68ba439 --- /dev/null +++ b/lib/memex/error_reporter.ex @@ -0,0 +1,57 @@ +defmodule Memex.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/memex/repo/migrator.ex b/lib/memex/repo/migrator.ex index de9cdb0..3355359 100644 --- a/lib/memex/repo/migrator.ex +++ b/lib/memex/repo/migrator.ex @@ -11,12 +11,15 @@ defmodule Memex.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(:memex, "priv/repo/migrations") - Ecto.Migrator.run(Memex.Repo, path, :up, all: true) + 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/memex_web/telemetry.ex b/lib/memex_web/telemetry.ex index 933a750..cf69c84 100644 --- a/lib/memex_web/telemetry.ex +++ b/lib/memex_web/telemetry.ex @@ -57,6 +57,30 @@ defmodule MemexWeb.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"),