Elixir: Timeout error when calling Logger.remove_backend/1 from Application.stop/1

[aaronrenner]

Environment

• Elixir & Erlang/OTP versions (elixir --version):
  
  
  
  • Elixir: 1.6.6, OTP 20.3.8.2
  
  
  • Elixir: 1.7.3, OTP 21.0.5
  
  
• Operating system: OS X 10.13.6

Current behavior

When I try to call Logger.remove_backend/1 from the Application.stop/1 or Application.prep_stop/1 callbacks, I get a timeout error.

my_logger_app master % iex -S mix
Erlang/OTP 21 [erts-10.0.5] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe]

Compiling 1 file (.ex)
Interactive Elixir (1.7.3) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> Application.stop(:my_logger_app)
:ok
iex(2)>
08:51:55.831 [info]  Application my_logger_app exited: :stopped

08:51:55.835 [error] :gen_event handler Logger.Config installed in Logger terminating
** (stop) exited in: :gen_server.call(:application_controller, {:set_env, :logger, :backends, [:console], []}, 5000)
    ** (EXIT) time out
Last message: {:remove_backend, MyLoggerApp.LoggerBackend}
State: {%{level: :debug, mode: :async, translators: [{Logger.Translator, :translate}], truncate: 8096, utc_log: false}, %{async_threshold: 15, discard_threshold: 500, keep_threshold: 375, sync_threshold: 20}}

08:51:55.836 [error] GenServer #PID<0.135.0> terminating
** (stop) {:EXIT, {:timeout, {:gen_server, :call, [:application_controller, {:set_env, :logger, :backends, [:console], []}, 5000]}}}
Last message: {:gen_event_EXIT, Logger.Config, {:EXIT, {:timeout, {:gen_server, :call, [:application_controller, {:set_env, :logger, :backends, [:console], []}, 5000]}}}}
State: {Logger, Logger.Config}

I've created a sample project that can be used to recreate the behavior: https://github.com/aaronrenner/my_logger_app

Expected behavior

The Logger should remove the backend without issue.

Please let me know if I should be removing the backend in a different way. If I don't explicitly call Logger.remove_backend/1 from the Application.stop/1 callback, the logger doesn't automatically get removed when I call Application.stop(:my_logger_app).

[josevalim]

The callbacks are sync, so nothing that depends on application will
shutdown properly. Generally speaking, it is unlikely to do any cleanup
there. Instead, you should organize the code in a way that the cleanup
happens when your application tree is shutting down. For example, you can
have a GenServer trapping exits that cleans up the logger backend on the
terminate callback.

--

José Valim
www.plataformatec.com.br
Skype: jv.ptec
Founder and Director of R&D

[aaronrenner]

I see. I'll try that approach. Thanks! 👍

[aaronrenner]

I just moved the Logger.add_backend and Logger.remove_backend logic into its own GenServer and I'm still seeing the issue.

Here's the commit where I made the change: https://github.com/aaronrenner/my_logger_app/commit/a2a189a0ad438a81d6ed4152120fdbbfe640f64a

And here's the new behavior

my_logger_app master % iex -S mix
Erlang/OTP 21 [erts-10.0.5] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe]

Interactive Elixir (1.7.3) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> Logger.Config.backends
[MyLoggerApp.LoggerBackend, :console]
iex(2)> Application.stop(:my_logger_app)
:ok
iex(3)>
10:22:21.660 [info]  Application my_logger_app exited: :stopped

10:22:21.663 [error] :gen_event handler Logger.Config installed in Logger terminating
** (stop) exited in: :gen_server.call(:application_controller, {:set_env, :logger, :backends, [:console], []}, 5000)
    ** (EXIT) time out
Last message: {:remove_backend, MyLoggerApp.LoggerBackend}
State: {%{level: :debug, mode: :async, translators: [{Logger.Translator, :translate}], truncate: 8096, utc_log: false}, %{async_threshold: 15, discard_threshold: 500, keep_threshold: 375, sync_threshold: 20}}

10:22:21.664 [error] GenServer #PID<0.126.0> terminating
** (stop) {:EXIT, {:timeout, {:gen_server, :call, [:application_controller, {:set_env, :logger, :backends, [:console], []}, 5000]}}}
Last message: {:gen_event_EXIT, Logger.Config, {:EXIT, {:timeout, {:gen_server, :call, [:application_controller, {:set_env, :logger, :backends, [:console], []}, 5000]}}}}
State: {Logger, Logger.Config}
iex(4)> Logger.Config.backends
[:console]

It does successfully remove the logger backend, but it takes about 5 seconds and I'm still seeing the timeout error.

[josevalim]

Thanks, I will investigate then!

[josevalim]

Hi @aaronrenner!

The only way we can make it work is if we no longer persist the result of Logger.add_backend and Logger.remove_backend to the application environment. Which in turns means that if the Logger supervision restarts, the logger backend you are adding through your application won't be restarted.

Ideally you would have your backend be listed under config :logger, :backends but that's an issue since your backends requires the application to be started to work, so I am quite unsure on the best way to move this forward.

Edit: I also understand that right now we are in a bad position in that you can't really remove the backend when the app shuts down. So we do need to address this.

[josevalim]

Also, thank you so much for providing apps that reproduce the error whenever you open up an issue. It makes our lives much much easier! :heart:

[aaronrenner]

@josevalim Thanks for your response on this. To give you more context, I'm using a custom logger backend to read log statement metadata and report errors to Honeybadger (trying to follow the "Erlang/OTP logger integration" pattern in the Elixir 1.7 release notes). In my case, Honeydew emits log statements with custom metadata attached and then I have a separate app that adds a logger backend on startup to listen to these log messages and send them up to Honeybadger. When that separate (listener) app is shut down, that's when I try to remove the logger backend I installed.

Sentry also shows an example of dynamically adding the LoggerBackend on startup, but they don't mention removing it when the application stops. https://github.com/getsentry/sentry-elixir#capture-crashed-process-exceptions

Thanks for pointing out that the compile-time config is the best option at the moment.
Ideally, when dealing with concerns like error reporting, it would we great if the error reporting application could just be started and go to work listening to the various log statements, without the developer having to add it to the list of logger backends at compile time.

Thanks so much for your response and looking into this for me. I definitely appreciate your help!

[josevalim]

Closing in favor of #8424 .