Ecto.Repo log setting not being used in migration runner

[deepfryed]

Elixir version

1.13.4

Database and Version

PostgreSQL 12.13

Ecto Versions

3.9.3

Database Adapter and Versions (postgrex, myxql, etc)

postgrex 0.16.5

Current behavior

Setting log to false in Repo config is overridden by the migration runner in https://github.com/elixir-ecto/ecto_sql/blob/0b34acaf54257980e0b7e89adbfc2d3da695b9f6/lib/ecto/migration/runner.ex#L329

Unsure if this is intentional and force the runner to rely on the log level of the default application logger (even that doesn't seem to be working, which is confusing)

and FWIW the --quiet option doesn't have an effect on this.

Expected behavior

The configured log level in Repo config should be used by migration runner.

[greg-rychlewski]

Please tell me if I'm misunderstanding, but when you define the logger level in your application you are defining a cut-off level for when logs should be skipped over. Not defining the level be used by the log function.

Ecto/Ecto SQL configuration is different because it's defining which level the log function will use. They have their own defaults independent of any other configuration in your application.

Ecto defaults to :debug because you probably don't want to see all your app's queries unless Ecto isn't doing what you expect.

Ecto SQL actually has 3 different types of logs, the one you are referring to defaults to :info because often people will want to see "Running migration ..." outside of debugging.

and FWIW the --quiet option doesn't have an effect on this.

When I use the quiet option it doesn't log the "Running migration ...". Would you be able to show a small reproducible script similar to this: https://github.com/wojtekmach/mix_install_examples/blob/main/ecto_sql.exs?

[deepfryed]

@greg-rychlewski I'll put together an example

What I'm trying to understand is if I set log: false in the Ecto Repo config in my application, the level passed to log_and_execute_ddl is false. Which is what's used in https://github.com/elixir-ecto/ecto_sql/blob/0b34acaf54257980e0b7e89adbfc2d3da695b9f6/lib/ecto/migration/runner.ex#L324

but that seems to be overridden in https://github.com/elixir-ecto/ecto_sql/blob/0b34acaf54257980e0b7e89adbfc2d3da695b9f6/lib/ecto/migration/runner.ex#L329 trying to confirm first if that's intentional.

[deepfryed]

@greg-rychlewski please see the stub phoenix app.

I've set the repo log setting to false and the application logger level is error

ecto_test.tar.gz

$ mix ecto.migrate --quiet

17:57:46.574 [info]  this should not be seen hello world!

[greg-rychlewski]

What I'm trying to understand is if I set log: false in the Ecto Repo config in my application, the level passed to log_and_execute_ddl is false. Which is what's used in

This one is intentional. It's the option passed here: https://hexdocs.pm/ecto_sql/Ecto.Migrator.html#up/4-options.

EDIT: to be more clear, it's the two options here:

level = Keyword.get(opts, :log, :info) sql = Keyword.get(opts, :log_migrations_sql, false)

It won't be the same as the Ecto Repo config because it's not expected the user will want them to be the same level by default. This is controlling what says "Running migration...". Probably you want to see that more than you want to see the queries from the application.

But now that I'm looking, there is not an option to change it in the mix task. You can't pass --log to override it. This is probably something we could add.

$ mix ecto.migrate --quiet 17:57:46.574 [info] this should not be seen hello world!

This part is unexpected to me . I'm not sure what is showing the notice from Postgres. I suspect it's the same as above but need to look more closely. Will get back to you unless Jose answers first.

[greg-rychlewski]

The notice messages from Postgrex seem to be controlled by what Postgres labels them as: https://github.com/elixir-ecto/ecto_sql/blob/f4fa96c8cb911824ddf41d699b13ba6dde053ed6/lib/ecto/adapters/postgres/connection.ex#L1033

So not controlled by any option.

[deepfryed]

righto, IMO it'd be less confusing if the log option in Repo config is used consistently everywhere within Ecto. It was a bit of a head scratcher for me today.

[deepfryed]

@greg-rychlewski would this be a better representation of the intent ?

  defp log_and_execute_ddl(repo, %{level: level, sql: sql}, command) do
    log(level, command(command))
    meta = Ecto.Adapter.lookup_meta(repo.get_dynamic_repo())
    {:ok, logs} = repo.__adapter__().execute_ddl(meta, command, timeout: :infinity, log: sql)

    Enum.each(logs, fn {ddl_log_level, message, metadata} ->
      ddl_log(ddl_log_level, level, message, metadata)
    end)

    :ok 
  end 

  defp ddl_log(_level, false, _msg, _metadata), do: :ok 
  defp ddl_log(_level, true, msg, metadata), do: Logger.log(:info, msg, metadata)
  defp ddl_log(level, _, msg, metadata), do: Logger.log(level, msg, metadata)

[greg-rychlewski]

TBH I'm not sure if that is the intent because the current logging options in Ecto SQL have very explicitly defined scope. The code seems to very deliberately not allow the user to change the log level emitted by Postgres.

I would have to defer to @josevalim to see if he agrees with your change suggestions.

[josevalim]

The migrations API use different log levels than the SQL log levels on purpose. We could, however, disable the DDL warnings if :log is false. PR welcome.