DBConnection logging exception when interacting with Event Store

Questions / Help
,
#1

Hi,

I am seeing the following exception in Phoenix server debug log when I execute a mutation to register a new user in my application:

[debug] Core.ProcessManagers.Registrator has been stopped by event 15 ("fefce8e5-aabc-4cd6-834c-44cae8ce6b4d"@5)
[error] an exception was raised logging %DBConnection.LogEntry{call: :prepare_execute, connection_time: 2358000, decode_time: 3000, idle_time: 12662000, 
params: ["\"Core.ProcessManagers.Registrator\"-\"fefce8e5-aabc-4cd6-834c-44cae8ce6b4d\""], pool_time: 1329000, 
query: %Postgrex.Query{cache: :reference, columns: nil, name: "", param_formats: nil, param_oids: nil, param_types: nil, ref: nil, result_formats: nil, result_oids: nil, result_types: nil, 
statement: ["DELETE FROM ", "public", ".snapshots\nWHERE source_uuid = $1;\n"], types: nil}, 
result: {:ok, %Postgrex.Query{cache: :reference, columns: nil, name: "", param_formats: [:binary], param_oids: [25], param_types: [Postgrex.Extensions.Raw], ref: #Reference<0.796564844.2413297668.48472>, result_formats: [], result_oids: nil, result_types: nil, 
statement: ["DELETE FROM ", "public", ".snapshots\nWHERE source_uuid = $1;\n"], types: {Postgrex.DefaultTypes, #Reference<0.796564844.2413428738.50179>}}, %Postgrex.Result{columns: nil, command: :delete, connection_id: 460, messages: [], num_rows: 1, rows: nil}}}: 
** (BadFunctionError) expected a function, got: false
    (db_connection 2.4.1) lib/db_connection.ex:1501: DBConnection.log/2
    (db_connection 2.4.1) lib/db_connection.ex:1479: DBConnection.log/5
    (postgrex 0.15.13) lib/postgrex.ex:313: Postgrex.query_prepare_execute/4
    (eventstore 1.3.2) lib/event_store/storage/snapshot.ex:63: EventStore.Storage.Snapshot.delete_snapshot/3
    (commanded 1.3.1) lib/commanded/process_managers/process_manager_instance.ex:114: Commanded.ProcessManagers.ProcessManagerInstance.handle_call/3
    (stdlib 3.17) gen_server.erl:721: :gen_server.try_handle_call/4
    (stdlib 3.17) gen_server.erl:750: :gen_server.handle_msg/6
    (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3

[debug] Core.ProcessManagers.Registrator confirming receipt of event: 15

I actually see DBConnection.LogEntry in each interaction with the event store always receiving the same BadFunctionError. I’ve already gone through the suggestions in this thread: Telemetry Logging Error, but have not made any progress. Any ideas what is going on here?

Environment

  • Elixir 1.12.3
  • Ecto 3.7.1
  • Postgres 13.5
#2

The code that’s raising BadFunctionError in DBConnection.log/2 is handling the log option passed in opts to most functions in DBConnection. This accepts either nil, an arity 1 function, or an MFA tuple - in particular, it DOES NOT accept false, which would cause exactly the error you’re seeing.

2 Likes
#3

@al2o3cr Thanks, your explanation makes sense. Now, my question is: why is false being passed in the opts? Nowhere in the stacktraces do I see a reference to my code. Could this be caused by a misconfiguration of one of those libraries? Or is it likely a bug in one of them that I should report?

Here are more BadFunctionErrors for reference (with sensitive data removed): db connection errors - Pastebin.com

#4

That’s my hypothesis - start by looking for EventStore config like config :my_app, MyApp.EventStore,.

The additional traces you posted interact with different parts of EventStore, further suggesting that it’s not a single bad call but an application-wide issue.

#5

Thanks for the pointers. It seems that I’ve found the source of the error. I have the following configuration:

postgres_config = [
  adapter: Ecto.Adapters.Postgres,
  username: System.get_env("POSTGRES_USER"),
  password: System.get_env("POSTGRES_PASSWORD"),
  hostname: System.get_env("POSTGRES_HOST"),
  port: "5432",
  show_sensitive_data_on_connection_error: true,
  log: false
]

When I remove log: false, the error disappears. Both the option and its value false are valid according to the docs, however: Ecto.Repo — Ecto v3.7.1. This is suggesting that the problem lies somewhere between Postgrex and DB Connection.

#6

@al2o3cr What do you think?

#7

eventstore doesn’t use Ecto, it talks directly to the Postgrex driver.

Ecto’s options in log: (like :debug or false) are transformed into what the adapter expects in Ecto.Adapters.SQL.with_log:

The configuration you pass to eventstore needs to match the expectations for log cited previously

1 Like