Release remote console does not use application logger configuration

[gmalkas]

Elixir and Erlang/OTP versions

Erlang/OTP 26 [erts-14.2.2] [source] [64-bit] [smp:24:24] [ds:24:24:10] [async-threads:1] [jit:ns]

Elixir 1.17.2 (compiled with Erlang/OTP 25)

Operating system

Debian 12

Current behavior

Given an application created with mix new bugapp and the following config/config.exs:

import Config

config :logger, level: :info

config :logger, :default_formatter,
  format: "$date $time $metadata[$level] $message\n",
  metadata: [:module, :request_id]

config :logger, :default_handler,
  config: [
        file: ~c"myapp.log",
        filesync_repeat_interval: 5000,
        file_check: 5000,
        max_no_bytes: 100_000_000,
        max_no_files: 10,
        compress_on_rotate: true
      ]

We build the release and start it:

$ MIX_ENV=prod mix release
$ _build/prod/rel/bugapp/bin/bugapp start

Then attach a console to it:

$ _build/prod/rel/bugapp/bin/bugapp remote
Erlang/OTP 26 [erts-14.2.2] [source] [64-bit] [smp:24:24] [ds:24:24:10] [async-threads:1] [jit:ns]

Interactive Elixir (1.17.2) - press Ctrl+C to exit (type h() ENTER for help)
iex(bugapp@iris)1> Application.get_env(:logger, :default_handler)
[
  config: [
    file: ~c"myapp.log",
    filesync_repeat_interval: 5000,
    file_check: 5000,
    max_no_bytes: 100000000,
    max_no_files: 10,
    compress_on_rotate: true
  ]
]
iex(bugapp@iris)2> Application.get_env(:logger, :default_formatter)
[
  format: "$date $time $metadata[$level] $message\n",
  metadata: [:module, :request_id]
]
iex(bugapp@iris)3> Logger.default_formatter
{Logger.Formatter,
 %Logger.Formatter{
   template: [:date, " ", :time, " ", :metadata, "[", :level, "] ", :message,
    "\n"],
   truncate: 8096,
   metadata: [:module, :request_id],
   colors: %{
     error: :red,
     enabled: true,
     info: :normal,
     warning: :yellow,
     debug: :cyan,
     notice: :normal,
     emergency: :red,
     alert: :red,
     critical: :red
   },
   utc_log?: false
 }}
iex(bugapp@iris)4> require Logger
Logger
iex(bugapp@iris)5> Logger.info("hello")
:ok

10:43:28.198 [info] hello
iex(bugapp@iris)6>

The file myapp.log is created but remains empty. The log message is printed to the attached console STDOUT but not written to the file, and the formatting used is not the one specified in the configuration.

This differs from starting a console directly:

$ iex -S mix
Erlang/OTP 26 [erts-14.2.2] [source] [64-bit] [smp:24:24] [ds:24:24:10] [async-threads:1] [jit:ns]

Generated bugapp app
Interactive Elixir (1.17.2) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> Logger.default_formatter
{Logger.Formatter,
 %Logger.Formatter{
   template: [:date, " ", :time, " ", :metadata, "[", :level, "] ", :message,
    "\n"],
   truncate: 8096,
   metadata: [:module, :request_id],
   colors: %{
     error: :red,
     enabled: true,
     info: :normal,
     warning: :yellow,
     debug: :cyan,
     notice: :normal,
     emergency: :red,
     alert: :red,
     critical: :red
   },
   utc_log?: false
 }}
iex(2)> require Logger
Logger
iex(3)> Logger.info("hello")
:ok
iex(4)>

In this case, the log message is written to myapp.log, as expected, and nothing is written to the console STDOUT.

Expected behavior

The expected behavior would be for the attached/remote console to use the configured handler and formatter. I could not figure out which handler/formatter is used to display the message on STDOUT, the Logger documentation does not mention this behavior with releases.

[josevalim]

Does it work if you do Application.stop(:logger) and then Application.start(:logger)?

[gmalkas]

Hey @josevalim , thanks for taking a look.

It does not seem to fix it, I get the same result:

$ _build/prod/rel/bugapp/bin/bugapp remote
Erlang/OTP 26 [erts-14.2.2] [source] [64-bit] [smp:24:24] [ds:24:24:10] [async-threads:1] [jit:ns]

Interactive Elixir (1.17.2) - press Ctrl+C to exit (type h() ENTER for help)
iex(bugapp@iris)1> Application.stop(:logger)
:ok
iex(bugapp@iris)2> Application.start(:logger)
:ok
iex(bugapp@iris)3> require Logger
Logger
iex(bugapp@iris)4> Logger.info("hello")
:ok

12:29:27.669 [info] hello
iex(bugapp@iris)5>

[josevalim]

I found out the root cause. By default, Elixir's Logger has a clause to avoid logging anything caused by remote consoles. You can do this:

config :logger, :default_handler,
  filters: [],
  config: [
        file: ~c"myapp.log",
        filesync_repeat_interval: 5000,
        file_check: 5000,
        max_no_bytes: 100_000_000,
        max_no_files: 10,
        compress_on_rotate: true
      ]

To remove said filter. I will improve the docs.

[gmalkas]

Thanks a lot for looking into this, your solution worked.

One thing I do not understand is why the remote console prints log messages to STDOUT with a different set of metadata than what is configured in the release. With filters: [], the logs are now appended to the log file as expected, but they are also still printed on the remote console STDOUT, with a different formatter (e.g. date is missing).

I couldn't find the relevant code in the Logger application.

[josevalim]

The answer is based on us having two nodes and they have different configs. The node running the remote terminal does not have your application started. Just the minimum to connect to the remote node.