Resolving errors for Logger backend on application start?

kenny-evitt

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

0 2639 12

2020-01-10 20:09:58 UTC

Showing Posts 1 to 10

Show Best Posts
Show All (oldest first)
Show All (newest first)

kenny-evitt

I created a question on Stack Overflow for this:

elixir - Resolving errors on application start for Logger backend and one of its dependencies not being initialized? - Stack Overflow

The first answer pointed out that the backend is not in fact an Elixir application and thus shouldn’t be included in the :applications key in the application/0 function in mix.exs. Unfortunately, removing it doesn’t seem to resolve these errors.

Post #1

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 #2

kenny-evitt

That’s an interesting post – thanks! I’ll consider pushing to cleanup those keys for our app at some point.

But the Logger backend we’re using isn’t apparently an application anyways so that’s a moot point in terms of the errors we’re seeing.

We’re going to try removing the backend dependency on Timex and tzdata next but I’m still curious what a solution that doesn’t involve that might be. It certainly doesn’t seem entirely incorrect for a Logger backend to rely on a dependency like this one does. I’m sure there’s some way for such a backend to wait for its dependencies to be initialized before it accepts events to be logged.

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 #4

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?

Post #5

kenny-evitt

I’m pretty sure that’s not likely to help with these errors either. The problem isn’t that tzdata is unavailable generally – it’s just not available immediately, when Logger starts sending events to the backend. In particular, the errors seem due to ETS table(s) not being immediately available when or while the app starts.

I haven’t found any info about implementing Logger backends that addresses what seems to be the root cause of these errors – the backend depending on tzdata but NOT waiting until it has been completely initialized.

Removing the (indirect) tzdata dependency from the backend is an obvious possible solution, but I suspect there’s an alternative solution that doesn’t require that.

Post #6

kenny-evitt

Sure!

From application/0 in mix.exs:

     applications: [:phoenix, :phoenix_pubsub, :phoenix_html, :cowboy, :logger, :gettext,
                    :phoenix_ecto, :postgrex, :timex, :httpoison, :scrivener_ecto,
                    :scrivener_html, :bamboo, :ex_aws, :geolix, :comeonin, :floki,
                    :guardian, :money, :oauther, :exjsx, :jsx,
                    :edeliver, :liquid, :sentry, :ex_cldr, :pdf_generator, :crontab,
                    :nimble_csv, :ecto_sql, :jason, :plug_cowboy, :bcrypt_elixir,
                    :ex_aws_s3, :openid_connect, :phoenix_live_view]]

The relevant config for Logger (for my dev environment):

config :logger,
  backends: [
    {LoggerLogstashBackend, :logstash_log},
    :console
  ],
  handle_sasl_reports: true,
  handle_otp_reports: true

config :logger, :logstash_log,
  host: "127.0.0.1",
  port: 4201,
  level: :info,
  ex_jsx_opts: [:uescape]

Thanks for the help!

Post #7

kenny-evitt

I just tried this. As I suspected, it doesn’t resolve or prevent these errors.

Post #8

kenny-evitt

Note that, in the :applications key value I shared just earlier, I’d already removed the :logger_logstash_backend as @axelson suggested. It didn’t seem to affect the errors. It definitely seems like, because that backend isn’t an Elixir application, it shouldn’t be included anyways, but it also definitely seems like Logger itself is starting the GenServer (or similar) for that backend directly.

I’d previously thought about trying to configure the backend later in the application startup, e.g. via a new application ‘start phase’, but Logger seems to require all backends to be configured at compile time so that doesn’t seem like a possible solution.

Post #9

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?

Post #10

Load more posts (2 remaining)