Ecto prints output from a lower logging level

Questions / Help
#1

Hi,

I’m running a pretty typical Phoenix project with Ecto 3.5.5, Ecto SQL 3.5.3, Phoenix Ecto 4.2.1 and Postgrex 0.15.7.

No matter what logging level is set in tests, I still can see debug output from Ecto in test environment.

To illustrate:

test "this will print SQL statements for sample data created in setup block" do
    IO.inspect(Application.get_all_env(:logger), label: "Logger settings")
end

produces

23:46:00.413 [debug] QUERY OK db=0.1ms
commit []

23:46:00.422 [debug] QUERY OK db=0.7ms queue=0.7ms
INSERT INTO "punters" ("email","inserted_at","updated_at","id") VALUES ($1,$2,$3,$4) ["email13@example.com", ~N[2020-11-24 21:46:00], ~N[2020-11-24 21:46:00], <<120, 113, 147, 93, 128, 51, 78, 38, 184, 20, 86, 38, 215, 137, 201, 237>>]

23:46:00.424 [debug] QUERY OK db=0.3ms queue=0.5ms
INSERT INTO "accounts" ("name","inserted_at","updated_at","id") VALUES ($1,$2,$3,$4) ["sample-account", ~N[2020-11-24 21:46:00], ~N[2020-11-24 21:46:00], <<115, 134, 200, 77, 161, 164, 68, 17, 184, 243, 92, 90, 95, 163, 95, 154>>]
Logger settings: [
  discard_threshold: 500,
  handle_sasl_reports: false,
  handle_otp_reports: true,
  console: [
    format: "$time $metadata[$level] $message\n",
    metadata: [:request_id]
  ],
  truncate: 8096,
  utc_log: false,
  compile_time_purge_matching: [],
  start_options: [],
  translator_inspect_opts: [],
  backends: [:console],
  discard_threshold_for_error_logger: 500,
  discard_threshold_periodic_check: 30000,
  sync_threshold: 20,
  level: :info,
  compile_time_application: nil,
  translators: [
    {Plug.Cowboy.Translator, :translate},
    {Logger.Translator, :translate}
  ]
]
.

Finished in 0.2 seconds

How is this possible?

#2

Hello!
Did you try rm -r _build/test? :slight_smile:
Are other (non-Ecto specific) debug logs printed too?
Do you have some kind of custom telemetry handler which may produce such behaviour?

#3

And what is your Logger.level (not the app env value)?

1 Like
#4

That’s precisely the problem - Logger.level is debug.

But where that can come from? A rogue dependency?

I’m not configuring logger in runtime in my code.

Also removed _build/test as @fuelen suggested but that didn’t change anything.

#5

How are you setting it to :info? In your config files? Can you grep all config :logger and make sure they are no overlapping configs?

#6

Yup, logger level is set in settings only.

❯ ag 'config :logger'                                                                                    
config/dev.exs
69:config :logger, :console, format: "[$level] $message\n"

config/config.exs
32:config :logger, :console,

config/prod.exs
17:config :logger, level: :info

config/test.exs
21:config :logger, level: :info

I also grepped deps folder and there is nothing fishy there on the surface. There should be no mystic in this situation, but I can’t put a finger on the cause yet.