Failure while translating Erlang's logger event (gen_statem)

[ruslandoga]

👋

Elixir and Erlang/OTP versions

Erlang/OTP 27 [erts-15.0] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [jit]

Elixir 1.17.1 (compiled with Erlang/OTP 27)

Operating system

mac

Current behavior

iex(1)> Mix.install [:postgrex]
:ok
iex(2)> Postgrex.start_link(backoff_type: :stop, max_restarts: 0, database: "plausible_dev")
{:ok, #PID<0.198.0>}

results in "Failure while translating Erlang's logger event"

01:40:10.853 [error] Postgrex.Protocol (#PID<0.200.0>) failed to connect: ** (DBConnection.ConnectionError) tcp connect (localhost:5432): connection refused - :econnrefused

01:40:10.855 [error] Failure while translating Erlang's logger event
** (MatchError) no match of right hand side value: %{label: {:gen_statem, :terminate}, name: #PID<0.200.0>, reason: {:error, %DBConnection.ConnectionError{message: "tcp connect (localhost:5432): connection refused - :econnrefused", severity: :error, reason: :error}, [{DBConnection.Connection, :handle_event, 4, [file: ~c"lib/db_connection/connection.ex", line: 122, error_info: %{module: Exception}]}, {:gen_statem, :loop_state_callback, 11, [file: ~c"gen_statem.erl", line: 3115]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]}]}, log: [], state: Postgrex.Protocol, queue: [internal: {:connect, :init}], modules: [DBConnection.Connection], client_info: :undefined, process_label: :undefined, callback_mode: &DBConnection.Connection.handle_event/4, postponed: [], timeouts: {0, []}, state_enter: false}
    (logger 1.17.1) lib/logger/translator.ex:306: Logger.Translator.report_gen_statem_terminate/2
    (logger 1.17.1) lib/logger/utils.ex:47: Logger.Utils.translate/5
    (logger 1.17.1) lib/logger/utils.ex:25: Logger.Utils.translator/2
    (kernel 10.0) logger_backend.erl:102: :logger_backend.do_apply_filters/4
    (kernel 10.0) logger_backend.erl:87: :logger_backend.apply_filters/4
    (kernel 10.0) logger_backend.erl:33: :logger_backend.log_allowed/3
    (stdlib 6.0) gen_statem.erl:4309: :gen_statem.terminate/7
    (stdlib 6.0) proc_lib.erl:329: :proc_lib.init_p_do_apply/3

** (EXIT from #PID<0.104.0>) shell process exited with reason: killed

[ruslandoga]

#13451 seems relevant since the code where the match fails was added in that PR.

elixir/lib/logger/lib/logger/translator.ex

Lines 297 to 306 in 6bfb95a

	%{
	client_info: client,
	name: name,
	reason: {kind, reason, stack},
	state: {state, data},
	queue: queue,
	postponed: postponed,
	callback_mode: callback_mode,
	state_enter: state_enter?
	} = report

doesn't match

%{
  label: {:gen_statem, :terminate},
  name: #PID<0.22566.0>,
  reason:
    {:error,
      %DBConnection.ConnectionError{
        message: "tcp connect (127.0.0.1:5432): connection refused - :econnrefused",
        severity: :error,
        reason: :error
      },
      [
        {DBConnection.Connection, :handle_event, 4,
        [file: ~c"lib/db_connection/connection.ex", line: 122, error_info: %{module: Exception}]},
        {:gen_statem, :loop_state_callback, 11, [file: ~c"gen_statem.erl", line: 3115]},
        {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]}
      ]},
  log: [],
  state: Postgrex.Protocol,
  queue: [internal: {:connect, :init}],
  modules: [DBConnection.Connection],
  process_label: :undefined,
  client_info: :undefined,
  callback_mode: &DBConnection.Connection.handle_event/4,
  postponed: [],
  timeouts: {0, []},
  state_enter: false
}

As state is Postgrex.Protocol and not {state, data}

[gitneko]

That seems to be because the gen_statem translator only seems to consider state_functions callback mode and not handle_event_function callback mode (which is used by Postgrex) and thus the matching fails because there's no tuple as state (it's just plain data).

[ruslandoga]

DBConnection.Connection which causes the error in OP also uses this callback mode: https://github.com/elixir-ecto/db_connection/blob/700cbf6a715ae813678de716e4409cc22c7e03e6/lib/db_connection/connection.ex#L45