# Resolving errors for Logger backend on application start?

**URL:** <https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069>\
**Category:** Questions\
**Tags:** logger\
**Created:** [January 6, 2020, 9:34pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069 "2020-01-06T21:34:07Z")\
**Posts on this page:** 13\
**Page:** 1

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 6, 2020, 9:34pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/1 "2020-01-06T21:34:07Z")

</div>

I’m using this backend in my application:

- [marcelog/logger\_logstash\_backend: Logstash backend for the Elixir Logger](https://github.com/marcelog/logger_logstash_backend)

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:

```elixir
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.

---

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 7, 2020, 7:12pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/2 "2020-01-07T19:12:19Z")

</div>

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](https://stackoverflow.com/questions/59631535/resolving-errors-on-application-start-for-logger-backend-and-one-of-its-dependen/59632691#59632691)

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.

---

<div class="post-metadata">

**Author:** ![axelson](https://forum.elixirforum.com/user_avatar/forum.elixirforum.com/axelson/32/26351_2.png) [@axelson](https://forum.elixirforum.com/u/axelson)\
**Post date:** [January 7, 2020, 7:14pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/3 "2020-01-07T19:14:10Z")

</div>

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

> **[Elixir :applications vs :extra\_applications - a guide](https://www.amberbit.com/blog/2017/9/22/elixir-applications-vs-extra_applications-guide/)**
>
> It has been confusing? Let me help.

---

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 7, 2020, 8:42pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/4 "2020-01-07T20:42:16Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![axelson](https://forum.elixirforum.com/user_avatar/forum.elixirforum.com/axelson/32/26351_2.png) [@axelson](https://forum.elixirforum.com/u/axelson)\
**Post date:** [January 7, 2020, 8:54pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/5 "2020-01-07T20:54:38Z")

</div>

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](https://github.com/bitwalker/timex/blob/master/mix.exs#L31)

---

<div class="post-metadata">

**Author:** ![Kintull](https://forum.elixirforum.com/user_avatar/forum.elixirforum.com/kintull/32/32644_2.png) [@Kintull](https://forum.elixirforum.com/u/Kintull)\
**Post date:** [January 7, 2020, 9:24pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/6 "2020-01-07T21:24:55Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 7, 2020, 9:38pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/7 "2020-01-07T21:38:41Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 7, 2020, 9:42pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/8 "2020-01-07T21:42:35Z")

</div>

Sure!

From `application/0` in `mix.exs`:

```elixir
     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):

```elixir
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!

---

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 7, 2020, 9:44pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/9 "2020-01-07T21:44:45Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 7, 2020, 9:49pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/10 "2020-01-07T21:49:05Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![Kintull](https://forum.elixirforum.com/user_avatar/forum.elixirforum.com/kintull/32/32644_2.png) [@Kintull](https://forum.elixirforum.com/u/Kintull)\
**Post date:** [January 8, 2020, 1:00am UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/11 "2020-01-08T01:00:55Z")

</div>

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?

---

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 8, 2020, 3:42pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/12 "2020-01-08T15:42:05Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![kenny-evitt](https://forum.elixirforum.com/letter_avatar_proxy/v4/letter/k/e47774/32.png) [@kenny-evitt](https://forum.elixirforum.com/u/kenny-evitt)\
**Post date:** [January 10, 2020, 8:09pm UTC](https://forum.elixirforum.com/t/resolving-errors-for-logger-backend-on-application-start/28069/13 "2020-01-10T20:09:58Z")

</div>

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`:

```elixir
       # Start `logger_logstash_backend` after `timex` (and `tzdata`) have been started:
       start_phases: [{:logger_logstash_backend, []}]

```

and in my main app module:

```elixir
  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

```