From 064d2d3988ba12444750e64affb4bf05021a9fd4 Mon Sep 17 00:00:00 2001 From: shibao Date: Sat, 4 Feb 2023 20:48:14 -0500 Subject: [PATCH] improve oban logging --- CHANGELOG.md | 1 + config/dev.exs | 5 +-- lib/cannery/application.ex | 21 +++++++++---- lib/cannery/error_reporter.ex | 57 +++++++++++++++++++++++++++++++++++ lib/cannery/repo/migrator.ex | 7 +++-- lib/cannery_web/telemetry.ex | 24 +++++++++++++++ 6 files changed, 105 insertions(+), 10 deletions(-) create mode 100644 lib/cannery/error_reporter.ex diff --git a/CHANGELOG.md b/CHANGELOG.md index 72281d84..7df1a593 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.8.1 - Update dependencies diff --git a/config/dev.exs b/config/dev.exs index f002e3c9..0aa76cc7 100644 --- a/config/dev.exs +++ b/config/dev.exs @@ -64,8 +64,9 @@ config :cannery, CanneryWeb.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/cannery/application.ex b/lib/cannery/application.ex index 7bf0b908..3daca201 100644 --- a/lib/cannery/application.ex +++ b/lib/cannery/application.ex @@ -4,6 +4,7 @@ defmodule Cannery.Application do @moduledoc false use Application + alias Cannery.ErrorReporter @impl true def start(_type, _args) do @@ -17,16 +18,24 @@ defmodule Cannery.Application do # Start the Endpoint (http/https) CanneryWeb.Endpoint, # Add Oban - {Oban, oban_config()} + {Oban, oban_config()}, + Cannery.Repo.Migrator # Start a worker by calling: Cannery.Worker.start_link(arg) # {Cannery.Worker, arg} ] - # Automatically migrate on start in prod - children = - if Application.get_env(:cannery, Cannery.Application, automigrate: false)[:automigrate], - do: children ++ [Cannery.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/cannery/error_reporter.ex b/lib/cannery/error_reporter.ex new file mode 100644 index 00000000..57ebf419 --- /dev/null +++ b/lib/cannery/error_reporter.ex @@ -0,0 +1,57 @@ +defmodule Cannery.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/cannery/repo/migrator.ex b/lib/cannery/repo/migrator.ex index f3cec946..0f7c2561 100644 --- a/lib/cannery/repo/migrator.ex +++ b/lib/cannery/repo/migrator.ex @@ -11,12 +11,15 @@ defmodule Cannery.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(:cannery, "priv/repo/migrations") Ecto.Migrator.run(Cannery.Repo, path, :up, all: true) end + + defp automigrate_enabled? do + Application.get_env(:cannery, Cannery.Application, automigrate: false)[:automigrate] + end end diff --git a/lib/cannery_web/telemetry.ex b/lib/cannery_web/telemetry.ex index 021f6c06..15a2dc8a 100644 --- a/lib/cannery_web/telemetry.ex +++ b/lib/cannery_web/telemetry.ex @@ -57,6 +57,30 @@ defmodule CanneryWeb.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"),