kenny-evitt
Resolving errors for Logger backend on application start?
I’m using this backend in my application:
In the application’s mix.exs file, in the application function, :logger_logstash_backend is included in the :applications key (after :timex, on which it relies).
When I start my app via iex -S mix, I see LOTS of errors like the following:
15:49:48.306 registered_name=Logger function=report_error/5 module=gen_event line=747 file=gen_event.erl pid=<0.2656.0> [error] :gen_event handler {LoggerLogstashBackend, :logstash_log} installed in Logger terminating
** (ArgumentError) argument error
(stdlib) :ets.lookup(:tzdata_current_release, :release_version)
lib/tzdata/release_reader.ex:74: Tzdata.ReleaseReader.current_release_from_table/0
lib/tzdata/release_reader.ex:17: Tzdata.ReleaseReader.simple_lookup/1
lib/tzdata/release_reader.ex:9: Tzdata.ReleaseReader.zone_and_link_list/0
lib/tzdata.ex:61: Tzdata.zone_exists?/1
lib/timezone/timezone.ex:358: Timex.Timezone.resolve/3
lib/logger_logstash_backend.ex:73: LoggerLogstashBackend.log_event/5
lib/logger_logstash_backend.ex:40: LoggerLogstashBackend.handle_event/2
(stdlib) gen_event.erl:577: :gen_event.server_update/4
(stdlib) gen_event.erl:559: :gen_event.server_notify/4
(stdlib) gen_event.erl:561: :gen_event.server_notify/4
(stdlib) gen_event.erl:300: :gen_event.handle_msg/6
(stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: {:info, #PID<0.63.0>, {Logger, ["Application ", "logger", " started at " | ":nonode@nohost"], {{2020, 1, 6}, {15, 49, 48, 224}}, [function: "info_started/2", module: :application_controller, line: 1926, file: "application_controller.erl", pid: #PID<0.43.0>]}}
State: %{ex_jsx_opts: [:uescape], host: '127.0.0.1', level: :info, metadata: [], name: :logstash_log, port: 4201, socket: #Port<0.2458>, type: "elixir"}
15:49:48.307 function=error_info/7 module=gen_server line=888 file=gen_server.erl pid=<0.2659.0> [error] GenServer #PID<0.2659.0> terminating
** (stop) {:EXIT, {:badarg, [{:ets, :lookup, [:tzdata_current_release, :release_version], []}, {Tzdata.ReleaseReader, :current_release_from_table, 0, [file: 'lib/tzdata/release_reader.ex', line: 74]}, {Tzdata.ReleaseReader, :simple_lookup, 1, [file: 'lib/tzdata/release_reader.ex', line: 17]}, {Tzdata.ReleaseReader, :zone_and_link_list, 0, [file: 'lib/tzdata/release_reader.ex', line: 9]}, {Tzdata, :zone_exists?, 1, [file: 'lib/tzdata.ex', line: 61]}, {Timex.Timezone, :resolve, 3, [file: 'lib/timezone/timezone.ex', line: 358]}, {LoggerLogstashBackend, :log_event, 5, [file: 'lib/logger_logstash_backend.ex', line: 73]}, {LoggerLogstashBackend, :handle_event, 2, [file: 'lib/logger_logstash_backend.ex', line: 40]}, {:gen_event, :server_update, 4, [file: 'gen_event.erl', line: 577]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 559]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 561]}, {:gen_event, :handle_msg, 6, [file: 'gen_event.erl', line: 300]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}]}}
Last message: {:gen_event_EXIT, {LoggerLogstashBackend, :logstash_log}, {:EXIT, {:badarg, [{:ets, :lookup, [:tzdata_current_release, :release_version], []}, {Tzdata.ReleaseReader, :current_release_from_table, 0, [file: 'lib/tzdata/release_reader.ex', line: 74]}, {Tzdata.ReleaseReader, :simple_lookup, 1, [file: 'lib/tzdata/release_reader.ex', line: 17]}, {Tzdata.ReleaseReader, :zone_and_link_list, 0, [file: 'lib/tzdata/release_reader.ex', line: 9]}, {Tzdata, :zone_exists?, 1, [file: 'lib/tzdata.ex', line: 61]}, {Timex.Timezone, :resolve, 3, [file: 'lib/timezone/timezone.ex', line: 358]}, {LoggerLogstashBackend, :log_event, 5, [file: 'lib/logger_logstash_backend.ex', line: 73]}, {LoggerLogstashBackend, :handle_event, 2, [file: 'lib/logger_logstash_backend.ex', line: 40]}, {:gen_event, :server_update, 4, [file: 'gen_event.erl', line: 577]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 559]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 561]}, {:gen_event, :handle_msg, 6, [file: 'gen_event.erl', line: 300]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}]}}}
State: {Logger, {LoggerLogstashBackend, :logstash_log}}
15:49:48.315 initial_call=Logger.Watcher.init/1 function=crash_report/4 module=proc_lib line=508 file=proc_lib.erl pid=<0.2659.0> [error] Process #PID<0.2659.0> terminating
** (exit) {:EXIT, {:badarg, [{:ets, :lookup, [:tzdata_current_release, :release_version], []}, {Tzdata.ReleaseReader, :current_release_from_table, 0, [file: 'lib/tzdata/release_reader.ex', line: 74]}, {Tzdata.ReleaseReader, :simple_lookup, 1, [file: 'lib/tzdata/release_reader.ex', line: 17]}, {Tzdata.ReleaseReader, :zone_and_link_list, 0, [file: 'lib/tzdata/release_reader.ex', line: 9]}, {Tzdata, :zone_exists?, 1, [file: 'lib/tzdata.ex', line: 61]}, {Timex.Timezone, :resolve, 3, [file: 'lib/timezone/timezone.ex', line: 358]}, {LoggerLogstashBackend, :log_event, 5, [file: 'lib/logger_logstash_backend.ex', line: 73]}, {LoggerLogstashBackend, :handle_event, 2, [file: 'lib/logger_logstash_backend.ex', line: 40]}, {:gen_event, :server_update, 4, [file: 'gen_event.erl', line: 577]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 559]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 561]}, {:gen_event, :handle_msg, 6, [file: 'gen_event.erl', line: 300]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}]}}
(stdlib) gen_server.erl:751: :gen_server.handle_common_reply/8
(stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Initial Call: Logger.Watcher.init/1
Ancestors: [Logger.BackendSupervisor, Logger.Supervisor, #PID<0.2654.0>]
Message Queue Length: 0
Messages: []
Links: [#PID<0.2658.0>, #PID<0.2656.0>]
Dictionary: []
Trapping Exits: true
Status: :running
Heap Size: 4185
Stack Size: 27
Reductions: 57169
15:49:48.316 function=do_restart/3 module=supervisor line=713 file=supervisor.erl pid=<0.2658.0> [error] Child {LoggerLogstashBackend, :logstash_log} of Supervisor Logger.BackendSupervisor terminated
** (exit) {:EXIT, {:badarg, [{:ets, :lookup, [:tzdata_current_release, :release_version], []}, {Tzdata.ReleaseReader, :current_release_from_table, 0, [file: 'lib/tzdata/release_reader.ex', line: 74]}, {Tzdata.ReleaseReader, :simple_lookup, 1, [file: 'lib/tzdata/release_reader.ex', line: 17]}, {Tzdata.ReleaseReader, :zone_and_link_list, 0, [file: 'lib/tzdata/release_reader.ex', line: 9]}, {Tzdata, :zone_exists?, 1, [file: 'lib/tzdata.ex', line: 61]}, {Timex.Timezone, :resolve, 3, [file: 'lib/timezone/timezone.ex', line: 358]}, {LoggerLogstashBackend, :log_event, 5, [file: 'lib/logger_logstash_backend.ex', line: 73]}, {LoggerLogstashBackend, :handle_event, 2, [file: 'lib/logger_logstash_backend.ex', line: 40]}, {:gen_event, :server_update, 4, [file: 'gen_event.erl', line: 577]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 559]}, {:gen_event, :server_notify, 4, [file: 'gen_event.erl', line: 561]}, {:gen_event, :handle_msg, 6, [file: 'gen_event.erl', line: 300]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 249]}]}}
Pid: #PID<0.2659.0>
Start Call: Logger.Watcher.start_link({Logger, {LoggerLogstashBackend, :logstash_log}, {LoggerLogstashBackend, :logstash_log}})
Restart: :transient
Shutdown: 5000
Type: :worker
15:49:48.316 function=report_progress/2 module=supervisor line=1419 file=supervisor.erl pid=<0.2658.0> [info] Child {LoggerLogstashBackend, :logstash_log} of Supervisor Logger.BackendSupervisor started
Pid: #PID<0.2678.0>
Start Call: Logger.Watcher.start_link({Logger, {LoggerLogstashBackend, :logstash_log}, {LoggerLogstashBackend, :logstash_log}})
Restart: :transient
Shutdown: 5000
Type: :worker
(The last event isn’t an error.)
The errors seem to be due to the backend relying on tzdata having been started and its ETS table existing.
I’ve been ignoring the errors until today. Today, for the first time, my entire application failed to start because there was finally enough of the above errors that the supervision tree itself crashed.
I tried moving the application for the backend from the :applications key to a start_phase function but that didn’t seem to help at all. I’m guessing it’s because the application for the backend is being started by Logger itself.
How can these errors be resolved or prevented? What should (ideally) be changed in either my application or the backend to avoid this or similar issues?
Is the problem that the backend relies on Timex and tzdata at all? Or is there some way the backend can be started by Logger and itself wait until tzdata (or Timex) has finished loading before it beings handling log events normally?
The GitHub project for the backend doesn’t seem to have been actively maintained for some time. I’m actually using a personal fork of the code currently. So I’m open to suggestions to change the backend code.
Marked As Solved
kenny-evitt
I was able to resolve/prevent all of these errors (and some new ones that appeared after the first set were resolved).
I removed the backend from the :applications key – that was good to do anyways. I’m going to try to cleanup the dependencies more generally later, e.g. remove the :applications key entirely and add only the necessary ‘extra’ apps to the :extra_applications key. (My app is older than those changes in Elixir; hence the stale state of this code/configuration.)
I modified my Logger configuration to NOT include this backend. Instead, I added a ‘start phase’ for the application; in mix.exs:
# Start `logger_logstash_backend` after `timex` (and `tzdata`) have been started:
start_phases: [{:logger_logstash_backend, []}]
and in my main app module:
def start_phase(:logger_logstash_backend, _start_type, _phase_args) do
IO.puts "Starting application start phase `:logger_logstash_backend`"
case Application.fetch_env(:my_app, :logger_logstash_backend) do
:error ->
IO.puts "No configuration value was found for the Logger Logstash backend."
{:ok, options} ->
backend = {LoggerLogstashBackend, :logstash_log}
# From the docs for `Logger.add_backend`:
#
# > Backends added by this function are not persisted. Therefore
# > if the Logger application or supervision tree is restarted,
# > the backend won't be available. If you need this guarantee,
# > then configure the backend via the application environment.
#
# This shouldn't be an issue for us as the `Logger` application and supervision tree don't seem
# to have ever needed to be restarted; just started normally when the app is started, i.e. when
# running the app locally in a `:dev` environment or when starting a new instance in production.
Logger.add_backend(backend)
Logger.configure_backend(backend, options)
end
:ok
end
Also Liked
axelson
Generally I wouldn’t fill out :applications, instead you generally want to use :extra_applications. This has some good background info on that:
axelson
If you want to maintain :applications manually it looks like you’ll need to add :tzdata before :timex and before :logger_logstash_backend since :timex depends on :tzdata.
Kintull
Could you please share applications of your mix.exs as it is now and also part of config.exs where you have config :logger?
Kintull
You could do a small workaround using Application.ensure_all_started(:timex) on start of your application before you do any logging. That’s if you really need to make it working as soon as possible.
I tried several setups, if applications are not present in config, Elixir builds applications-to-start-before-main-application-runs using deps. If something is specified in applications section it will overwrite the list that is built from deps. Finally Elixir merges this list with extra_applications section.
logger_logstash_backend's mix.exs contains :timex as a dependency which depends on :tzdata. It means that :tzdata have to be started before main application.
Could you please try to rename applications section to extra_applications and try again?
Popular in Questions
Other popular topics
Latest on Elixir Forum
Sponsor Spotlight
We build reliable cloud platforms for business-critical systems.
Categories:
Sub Categories:
Forums
Our Sponsors
Build Elixir applications with speed and confidence.
Supporting innovation across the BEAM ecosystem.
We build reliable cloud platforms for business-critical systems.
Catch errors, track performance, monitor hosts and more.
Practical resources that improve the lives of professional developers.
Producing high quality Elixir screencasts since 2017.
The deployment platform built for Elixir: PaaS ease, VPS control.
Courses that'll move you from confusion to "Aha, now I get it!"