honeydew icon indicating copy to clipboard operation
honeydew copied to clipboard

Creates a behaviour for `Honeydew.Logger` module

Open sezaru opened this issue 4 years ago • 0 comments

Hello,

This is a suggestion to make Honeydew.Logger a behaviour to allow custom adapters for it.

The reasoning is that depending on the job nature for crash handle, you can easily get overwhelmed with a lot of log warn messages that are very verbose like this one:

01:45:59.066 [warn] #PID<0.753.0> Honeydew.Logger "job_failed/2" "lib/honeydew/logger.ex" 38 
↳ Job failed due to exception. %Honeydew.Job{by: :"[email protected]", completed_at: nil, delay_secs: 0, enqueued_at: 1604810753704, failure_private: nil, from: nil, job_monitor: #PID<0.24453.43>, private: 226020, queue: :fcm_sender, result: {:error, %Honeydew.Crash{reason: %Notification.Errors.ApiError{body: "{\n  \"error\": {\n    \"code\": 503,\n    \"message\": \"The service is currently unavailable.\",\n    \"status\": \"UNAVAILABLE\"\n  }\n}\n", reason: "status code: 503"}, stacktrace: [{Notification.Middlewares.FCM.Response, :parse_response, 1, [file: 'lib/notification/middlewares/fcm/response.ex', line: 19]}, {Tesla.Middleware.JSON, :call, 3, [file: 'lib/tesla/middleware/json.ex', line: 54]}, {Honeydew.JobRunner, :do_run, 1, [file: 'lib/honeydew/job_runner.ex', line: 58]}, {Honeydew.JobRunner, :handle_continue, 2, [file: 'lib/honeydew/job_runner.ex', line: 79]}, {:gen_server, :try_dispatch, 4, [file: 'gen_server.erl', line: 680]}, {:gen_server, :loop, 7, [file: 'gen_server.erl', line: 431]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 226]}], type: :exception}}, started_at: nil, task: {:send_to_fcm, [...]}}
** (Notification.Errors.ApiError) Notification.ApiError - '"status code: 503"' with body "{\n  \"error\": {\n    \"code\": 503,\n    \"message\": \"The service is currently unavailable.\",\n    \"status\": \"UNAVAILABLE\"\n  }\n}\n".
    (notification 0.1.0) lib/notification/middlewares/fcm/response.ex:19: Notification.Middlewares.FCM.Response.parse_response/1
    (tesla 1.3.3) lib/tesla/middleware/json.ex:54: Tesla.Middleware.JSON.call/3
    (honeydew 1.4.5) lib/honeydew/job_runner.ex:58: Honeydew.JobRunner.do_run/1
    (honeydew 1.4.5) lib/honeydew/job_runner.ex:79: Honeydew.JobRunner.handle_continue/2
    (stdlib 3.13.2) gen_server.erl:680: :gen_server.try_dispatch/4
    (stdlib 3.13.2) gen_server.erl:431: :gen_server.loop/7
    (stdlib 3.13.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3

This change would allow the user to create a custom adapter for the Honeydew log messages so he can filter some messages out or modify it to be less verbose.

The implementation could be something like this:

defmodule Honeydew.Logger do
  alias Honeydew.{Crash, Job}

  @callback worker_init_crashed(module, Crash.t()) :: :ok
  @callback job_failed(Job.t(), Crash.t()) :: :ok
end

defmodule Honeydew.Logger.DefaultAdapter do
  @moduledoc false

  alias Honeydew.Crash
  alias Honeydew.Logger.Metadata
  alias Honeydew.Job

  require Logger

  @behaviour Honeydew.Logger

  @impl Honeydew.Logger
  def worker_init_crashed(module, %Crash{type: :exception, reason: exception} = crash) do
    Logger.warn(fn ->
      {
        "#{module}.init/1 must return {:ok, state :: any()}, but raised #{inspect(exception)}",
        honeydew_crash_reason: Metadata.build_crash_reason(crash)
      }
    end)
  end

  def worker_init_crashed(module, %Crash{type: :throw, reason: thrown} = crash) do
    Logger.warn(fn ->
      {
        "#{module}.init/1 must return {:ok, state :: any()}, but threw #{inspect(thrown)}",
        honeydew_crash_reason: Metadata.build_crash_reason(crash)
      }
    end)
  end

  def worker_init_crashed(module, %Crash{type: :bad_return_value, reason: value} = crash) do
    Logger.warn(fn ->
      {
        "#{module}.init/1 must return {:ok, state :: any()}, got: #{inspect(value)}",
        honeydew_crash_reason: Metadata.build_crash_reason(crash)
      }
    end)
  end

  @impl Honeydew.Logger
  def job_failed(%Job{} = job, %Crash{type: :exception} = crash) do
    Logger.warn(fn ->
      {
        """
        Job failed due to exception. #{inspect(job)}
        #{format_crash_for_log(crash)}
        """,
        honeydew_crash_reason: Metadata.build_crash_reason(crash), honeydew_job: job
      }
    end)
  end

  def job_failed(%Job{} = job, %Crash{type: :throw} = crash) do
    Logger.warn(fn ->
      {
        """
        Job failed due to uncaught throw. #{inspect(job)}",
        #{format_crash_for_log(crash)}
        """,
        honeydew_crash_reason: Metadata.build_crash_reason(crash), honeydew_job: job
      }
    end)
  end

  def job_failed(%Job{} = job, %Crash{type: :exit} = crash) do
    Logger.warn(fn ->
      {
        """
        Job failed due unexpected exit. #{inspect(job)}",
        #{format_crash_for_log(crash)}
        """,
        honeydew_crash_reason: Metadata.build_crash_reason(crash), honeydew_job: job
      }
    end)
  end

  defp format_crash_for_log(%Crash{type: :exception, reason: exception, stacktrace: stacktrace}) do
    Exception.format(:error, exception, stacktrace)
  end

  defp format_crash_for_log(%Crash{type: :throw, reason: exception, stacktrace: stacktrace}) do
    Exception.format(:throw, exception, stacktrace)
  end

  defp format_crash_for_log(%Crash{type: :exit, reason: reason, stacktrace: []}) do
    Exception.format(:exit, reason, [])
  end
end

And the user can configure it when starting the queue:

    Honeydew.start_queue(:fcm_sender,
      queue: {Queues.PriorityMnesia, disc_copies: nodes},
      failure_mode: {ExponentialRetry, times: 10, base: 2},
      logger_adapter: MyCustomLoggerAdapter
    )

sezaru avatar Nov 10 '20 15:11 sezaru