Logger.put_module_level does not silence preloads

[SteffenDE]

Elixir version

1.17.0-dev

Database and Version

PostgreSQL 14

Ecto Versions

Ecto 3.11

Database Adapter and Versions (postgrex, myxql, etc)

postgrex 0.17.5

Current behavior

I have a job that runs some queries that I'd like to exclude from logging in development. I'm using Logger.put_module_level, which works just fine, except for queries caused by preloads. I also tried setting Logger.put_process_level, but that also only works for the initial queries and not the preloads.

Expected behavior

As the logged information from the stacktrace includes the originating module, it would be nice if it used this information to lookup a level using Logger.get_module_level or maybe even Logger.get_process_level using the callers?

Maybe there are some other ideas on how to achieve this.

I'd be happy to work on a PR for this with some feedback on what the correct approach could be.

[v0idpwn]

Not exactly a solution, but a workaround for the case this doesn't go anywhere, or for a quick fix: preload supports the :on_preloader_spawn option, which allows you to run arbitrary code before the preload is performed. Using this option, you can propagate the logger level:

logger_level = Logger.get_process_level(self())
MySchema
|> MyApp.Repo.all()
|> MyApp.Repo.preload([:my_association], on_preloader_spawn: fn ->
  Logger.put_process_level(self(), logger_level)
end)

Additionally, by using the default_options callback, you can off-load this logic to your repo, avoiding the need to pass the option every time.

[SteffenDE]

Thank you very much, for me this is an acceptable workaround (I have some other customizations in the repo already):

def default_options(_operation) do
  [...] ++ maybe_custom_log_level()
end

defp maybe_custom_log_level do
  level = Process.get({__MODULE__, :override_log_level})

  if is_nil(level) do
    []
  else
    [log: level, on_preloader_spawn: fn -> put_log_level(level) end]
  end
end

@doc false
def put_log_level(level) do
  Process.put({__MODULE__, :override_log_level}, level)
end

@doc false
def clear_log_level do
  Process.delete({__MODULE__, :override_log_level})
end

@doc false
def with_log_level(level, callback) do
  put_log_level(level)
  callback.()
after
  clear_log_level()
end

and then wrapping the job in the code with a

MyApp.Repo.with_log_level(false, fn ->
  # code that executes some queries with preloads
end)

[josevalim]

@v0idpwn nice! Do you think we should do it by default? (the log level parts?)

[v0idpwn]

I think it's a good idea, it's what I would expect Ecto to do. My only (slightly unrelated) question is if we should perhaps auto-propagate logger metadata as well. If not, we should maybe mention it in the documentation.