Honeybadger.Logger process starts in wrong environments and terminates/times out for no clear reason

[kwayebopp]

Hi! I have an Elixir/Phoenix app using Honeybadger for error reporting and logging. During development (and I suspect occasionally in production) the server throws a DBConnection.ConnectionError. This happens from time to time, and I'm working on optimizing queries. What is strange is that I see the Honeybadger application is running as well, as I've tried to disable it in the development environment.

Here's an example of one such error:

[info] Postgrex.Protocol (#PID<0.435.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1575.0> exited
[error] #PID<0.1563.0> running CoolAppWeb.Endpoint (connection #PID<0.1548.0>, stream id 3) terminated
Server: subdomain.localhost:4000 (http)
Request: POST /graphql
** (exit) exited in: Task.await(%Task{owner: #PID<0.1563.0>, pid: #PID<0.1575.0>, ref: #Reference<0.3695852442.3919314945.95728>}, 5000)
** (EXIT) time out
[error] :gen_event handler Honeybadger.Logger installed in Logger terminating
** (FunctionClauseError) no function clause matching in Honeybadger.Notice.new/3
(honeybadger) lib/honeybadger/notice.ex:36: Honeybadger.Notice.new(:timeout, %{context: %{}}, {Task, :await, [%Task{owner: #PID<0.1563.0>, pid: #PID<0.1575.0>, ref: #Reference<0.3695852442.3919314945.95728>}, 5000]})
(honeybadger) lib/honeybadger.ex:207: Honeybadger.notify/3
(honeybadger) lib/honeybadger/logger.ex:35: Honeybadger.Logger.handle_event/2
(stdlib) gen_event.erl:577: :gen_event.server_update/4
(stdlib) gen_event.erl:559: :gen_event.server_notify/4
(stdlib) gen_event.erl:300: :gen_event.handle_msg/6
(stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: {:error, #PID<0.427.0>, {Logger, ["#PID<0.1563.0>", " running ", "CoolAppWeb.Endpoint", [" (connection ", "#PID<0.1548.0>", ", stream id ", "3", 41], " terminated\n", [["Server: ", "subdomain.localhost", ":", "4000", 32, 40, "http", 41, 10], ["Request: ", "POST", 32, "/graphql", 10]] | "** (exit) exited in: Task.await(%Task{owner: #PID<0.1563.0>, pid: #PID<0.1575.0>, ref: #Reference<0.3695852442.3919314945.95728>}, 5000)\n ** (EXIT) time out"], {{2019, 12, 6}, {12, 39, 18, 576}}, [crash_reason: {:timeout, {Task, :await, [%Task{owner: #PID<0.1563.0>, pid: #PID<0.1575.0>, ref: #Reference<0.3695852442.3919314945.95728>}, 5000]}}, pid: #PID<0.1548.0>]}}
State: %{level: nil}
[error] GenServer #PID<0.409.0> terminating
** (stop) {:EXIT, {:function_clause, [{Honeybadger.Notice, :new, [:timeout, %{context: %{}}, {Task, :await, [%Task{owner: #PID<0.1563.0>, pid: #PID<0.1575.0>, ref: #Reference<0.3695852442.3919314945.95728>}, 5000]}], [file: 'lib/honeybadger/notice.ex', line: 36]}, {Honeybadger, :notify, 3, [file: 'lib/honeybadger.ex', line: 207]}, {Honeybadger.Logger, :handle_event, 2, [file: 'lib/honeybadger/logger.ex', line: 35]}, {:gen_event, :server_update, 4, [file: 'gen_event.erl', line: 577]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 559]}, {:gen_event, :handle_msg, 6, [file: 'gen_event.erl', line: 300]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}]}}
Last message: {:gen_event_EXIT, Honeybadger.Logger, {:EXIT, {:function_clause, [{Honeybadger.Notice, :new, [:timeout, %{context: %{}}, {Task, :await, [%Task{owner: #PID<0.1563.0>, pid: #PID<0.1575.0>, ref: #Reference<0.3695852442.3919314945.95728>}, 5000]}], [file: 'lib/honeybadger/notice.ex', line: 36]}, {Honeybadger, :notify, 3, [file: 'lib/honeybadger.ex', line: 207]}, {Honeybadger.Logger, :handle_event, 2, [file: 'lib/honeybadger/logger.ex', line: 35]}, {:gen_event, :server_update, 4, [file: 'gen_event.erl', line: 577]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 559]}, {:gen_event, :handle_msg, 6, [file: 'gen_event.erl', line: 300]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}]}}}
State: {Logger, Honeybadger.Logger}

As stated above, I tried to take measures to ensure that Honeybadger doesn't run during development. In mix.exs a function is used to collect the appropriate extra_applications:

mix.exs:

  defp get_extra_applications do
    apps = [
      :logger,
      :runtime_tools,
      #some other applications...
    ]

    case Mix.env() do
      :prod -> apps ++ [:honeybadger] # we only want honeybadger running in production
      :test -> apps ++ [:ex_machina] 
      :dev -> apps
    end
  end

  def application do
    [
      mod: {CoolApp.Application, []},
      extra_applications: get_extra_applications()
    ]
  end

In addition to that, I tried to make sure that the Honeybadger.Plug is only conditionally used in router.ex:

defmodule CoolAppWeb.Router do
  use CoolAppWeb, :router

  if Mix.env() === :prod do # only use the plug in production
    use Honeybadger.Plug
  end

...

This behavior is probably not correct, so I think I maybe have something wrong in my setup somewhere. In the interest of putting everything up for examination I've included the dev and prod configs.

config.exs:

config :honeybadger,
app: :cool_app,
exclude_envs: [:dev, :test],
filter: Honeybadger.Filter.Default,
filter_keys: [:password],
api_key: System.get_env("HONEYBADGER_API_KEY")

dev.exs:

config :cool_app, CoolApp.Repo,
  adapter: Ecto.Adapters.Postgres,
  username: ...,
  password: ...,
  database: ...,
  hostname: "localhost",
  pool_size: String.to_integer(System.get_env("POOL_SIZE") || "10"),
  queue_target: 5_000

config :honeybadger, environment_name: :dev

prod.exs:

config :cool_app, CoolApp.Repo,
  adapter: Ecto.Adapters.Postgres,
  url: System.get_env("DATABASE_URL"),
  pool_size: String.to_integer(System.get_env("POOL_SIZE") || "10"),
  ssl: true,
  queue_target: 5_000

config :honeybadger, environment_name: :prod

This problem is a real head-scratcher for me, so any and all help or suggestions are greatly appreciated!

[sorentwo]

You can disable the logger in dev:

config :honeybadger, environment_name: :dev, use_logger: false

However, that shouldn't be necessary. The logger shouldn't ever crash when attempting to send a notice. I'm curious how the call to Notice.new/3 got a single stack line and not a list of stacklines:

(honeybadger) lib/honeybadger/notice.ex:36: Honeybadger.Notice.new(:timeout, %{context: %{}}, {Task, :await, [%Task{owner: #PID<0.1563.0>, pid: #PID<0.1575.0>, ref: #Reference<0.3695852442.3919314945.95728>}, 5000]})

I have a potential fix for that issue ready, but I can't recreate it with any tests.

[kwayebopp]

Looking at the line, the error is a timeout, and the integer at the end is the same value as my :queue_target config. Maybe that has something to do with it?

[sorentwo]

That is the format of every error tuple in a stacktrace. The strange part is that it isn't part of a list.

[jimmybot]

Here to chime in that we just experienced a similar issue where the Honeybadger.Notice.new call fails because the stacktrace is a tuple and not a list.

** (FunctionClauseError) no function clause matching in Honeybadger.Notice.new/4
    (honeybadger 0.15.0) lib/honeybadger/notice.ex:38: Honeybadger.Notice.new(:timeout, %{breadcrumbs: %{enabled: true, trail: [%Honeybadger.Breadcrumbs.Breadcrumb{category: "error", message: "ErlangError", metadata: %{message: "Erlang error: :timeout"}, timestamp: ~U[2021-03-12 16:26:05.940350Z]}, %Honeybadger.Breadcrumbs.Breadcrumb{category: "notice", message: "Honeybadger Notice: timeout", metadata: %{}, timestamp: ~U[2021-03-12 16:26:05.940373Z]}]}, context: %{domain: [:cowboy], erl_level: :error, error_logger: %{tag: :error}, gl: #PID<0.444.0>, report_cb: #Function<0.118689316/1 in :error_logger."-fun.report_to_format/1-">, time: 1615566365940243}}, {GenServer, :call, [:XXX, {:valid_account, "XXX:XXX"}, 5000]}, "")
    (honeybadger 0.15.0) lib/honeybadger.ex:297: Honeybadger.notify/2
    (honeybadger 0.15.0) lib/honeybadger/logger.ex:37: Honeybadger.Logger.handle_event/2
    (stdlib 3.13.2) gen_event.erl:620: :gen_event.server_update/4
    (stdlib 3.13.2) gen_event.erl:602: :gen_event.server_notify/4
    (stdlib 3.13.2) gen_event.erl:343: :gen_event.handle_msg/6
    (stdlib 3.13.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3