From 29d13b5b1fb849e9e8d245477c381ef705b11440 Mon Sep 17 00:00:00 2001 From: shibao Date: Sat, 4 Feb 2023 20:48:14 -0500 Subject: [PATCH 1/2] 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 | 11 ++++--- lib/cannery_web/telemetry.ex | 24 +++++++++++++++ 6 files changed, 107 insertions(+), 12 deletions(-) create mode 100644 lib/cannery/error_reporter.ex diff --git a/CHANGELOG.md b/CHANGELOG.md index 72281d8..7df1a59 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 f002e3c..0aa76cc 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 7bf0b90..3daca20 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 0000000..57ebf41 --- /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 f3cec94..5eca8d5 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) + 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/cannery_web/telemetry.ex b/lib/cannery_web/telemetry.ex index 021f6c0..15a2dc8 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"), From a055491f6b07da547f5b104becc9cc096bb0b069 Mon Sep 17 00:00:00 2001 From: shibao Date: Sat, 4 Feb 2023 21:51:09 -0500 Subject: [PATCH 2/2] fix tests --- config/runtime.exs | 6 ++++-- config/test.exs | 3 +++ lib/cannery/accounts.ex | 2 ++ lib/cannery/accounts/invites.ex | 4 +++- 4 files changed, 12 insertions(+), 3 deletions(-) diff --git a/config/runtime.exs b/config/runtime.exs index 4778318..7b19085 100644 --- a/config/runtime.exs +++ b/config/runtime.exs @@ -44,8 +44,6 @@ config :cannery, Cannery.Repo, pool_size: String.to_integer(System.get_env("POOL_SIZE", "10")), socket_options: maybe_ipv6 -config :cannery, Cannery.Accounts, registration: System.get_env("REGISTRATION", "invite") - config :cannery, CanneryWeb.Endpoint, url: [scheme: "https", host: host, port: 443], http: [ @@ -56,6 +54,10 @@ config :cannery, CanneryWeb.Endpoint, ], server: true +if config_env() in [:dev, :prod] do + config :cannery, Cannery.Accounts, registration: System.get_env("REGISTRATION", "invite") +end + if config_env() == :prod do # The secret key base is used to sign/encrypt cookies and other secrets. # A default value is used in config/dev.exs and config/test.exs but you diff --git a/config/test.exs b/config/test.exs index 718ffc7..caed05b 100644 --- a/config/test.exs +++ b/config/test.exs @@ -22,6 +22,9 @@ config :cannery, CanneryWeb.Endpoint, # In test we don't send emails. config :cannery, Cannery.Mailer, adapter: Swoosh.Adapters.Test +# Don't require invites for signups +config :cannery, Cannery.Accounts, registration: "public" + # Print only warnings and errors during test config :logger, level: :warn diff --git a/lib/cannery/accounts.ex b/lib/cannery/accounts.ex index fbe31e1..71f4517 100644 --- a/lib/cannery/accounts.ex +++ b/lib/cannery/accounts.ex @@ -117,6 +117,8 @@ defmodule Cannery.Accounts do :passed """ + @spec register_user(attrs :: map()) :: + {:ok, User.t()} | {:error, :invalid_token | User.changeset()} @spec register_user(attrs :: map(), Invite.token() | nil) :: {:ok, User.t()} | {:error, :invalid_token | User.changeset()} def register_user(attrs, invite_token \\ nil) do diff --git a/lib/cannery/accounts/invites.ex b/lib/cannery/accounts/invites.ex index 88be85e..7f8e955 100644 --- a/lib/cannery/accounts/invites.ex +++ b/lib/cannery/accounts/invites.ex @@ -85,7 +85,9 @@ defmodule Cannery.Accounts.Invites do end end - @spec get_invite_by_token(Invite.token()) :: {:ok, Invite.t()} | {:error, :invalid_token} + @spec get_invite_by_token(Invite.token() | nil) :: {:ok, Invite.t()} | {:error, :invalid_token} + defp get_invite_by_token(token) when token in [nil, ""], do: {:error, :invalid_token} + defp get_invite_by_token(token) do Repo.one( from i in Invite,