Resolving errors for Logger backend on application start?

Questions / Help
#1

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.

#2

I created a question on Stack Overflow for this:

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.

#3

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

2 Likes
#4

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.

#5

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.

1 Like
#6

Could you please share applications of your mix.exs as it is now and also part of config.exs where you have config :logger?

1 Like
#7

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.

#8

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!

#9

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

#10

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.

#11

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?

1 Like
#12

Thanks for the feedback!

Where should I put Application.ensure_all_started(:timex)?

The logging that seems to be failing isn’t anything explicitly in my application’s code; it’s various dependencies AFAICT.

I’m going to try removing the :applications key entirely and then adding any applications not automatically inferred by Elixir to the :extra_applications key as you and others have suggested.

I just discovered that Logger backends can be dynamically configured via Logger.add_backend/2. I also want to try removing this backend from the Logger config data and calling that function in a separate start_phase function, and possibly explicitly check that the tzdata ETS table(s) are ready and accessible before doing so.

#13

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