kenny-evitt

Resolving errors for Logger backend on application start?

I’m using this backend in my application:

marcelog/logger_logstash_backend: Logstash backend for the Elixir Logger

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.

12 comments

#logger

7 2260 12

2020-01-10 20:09:58 UTC

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

Post #13

Also Liked

axelson

Scenic Core Team

Generally I wouldn’t fill out :applications, instead you generally want to use :extra_applications. This has some good background info on that:

Post #3

axelson

Scenic Core Team

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.

https://github.com/bitwalker/timex/blob/master/mix.exs#L31

Post #5