Call for testers: new Elixir Logger backend

Chat / Discussions
,
1

As some of you are aware (and the rest will be if they read this post) the OTP 21 introduced new logger module which provides real-life logger to the Erlang itself. For a long time (I think that Elixir 1.7 was the first one with integration) Elixir was hooking into it to listen for messages sent by Erlang libraries, but it was only one way integration (so messages sent by Elixir wasn’t available to Erlang handlers).

But it is no more, as PR 9333 was merged to the master, now Logger is a thin wrapper over Erlang’s built in functionality with compatibility layer on top to support all backends that already are there.

However that one is a huge change and I with @josevalim were working on it for over a month to find all problems and provide good implementation. We are pretty confident with the implementation, but nothing is better than testing in production. So this is time for all of You, embrace your fears and boldly go where no one has gone before. We need You to test it with your applications (of course locally, we do not encourage anyone to test it in real production).

iu
iu1280×720 58 KB

Please, test it, break it, report it.

For those who are interested in “what it will give us anyway?”:

  • Unified metadata between loggers (and potentially other libraries like opentelemetry)
  • Out of the box integration with Lager as Lager hooks into logger as well
  • Built in support for logging to disk via logger_disk_log_h

These are for now, in future the changes will include:

  • Additional log levels (notice, critical, alert, emergency)
  • Support for structured logging
  • Module and application level control about logs verbosity

But anyway, play with it, test it, and if you break it, let us know so we can polish it before final release of 1.10 (oh, by the way this will make Elixir 1.10 OTP 21+ only).

44 Likes
3

Thanks for these contributions! I installed elixir master using asdf:

asdf install elixir ref:67dec4683de49e6e8153f9c49d0a0a179c550f9f

and gave it a try in a phoenix app where I have:

config :logger, level: :warn

And I get:

Erlang/OTP 22 [erts-10.4.3] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe]

warning: the level for Erlang's logger was set to :debug, but Elixir's logger was set to :warn. Elixir's logger value will take higher precedence
  (logger 1.10.0-dev) lib/logger/app.ex:96: Logger.App.add_elixir_handler/2
  (logger 1.10.0-dev) lib/logger/app.ex:24: Logger.App.start/2
  (kernel 6.4.1) application_master.erl:277: :application_master.start_it_old/4

** (MatchError) no match of right hand side value: {:error, {:bad_return, {{Logger.App, :start, [:normal, []]}, {:EXIT, {{:badmatch, {:error, {:invalid_level, :warn}}}, [{Logger.App, :add_elixir_handler, 2, [file: 'lib/logger/app.ex', line: 103]}, {Logger.App, :start, 2, [file: 'lib/logger/app.ex', line: 24]}, {:application_master, :start_it_old, 4, [file: 'application_master.erl', line: 277]}]}}}}}
    (mix 1.10.0-dev) lib/mix/cli.ex:106: Mix.CLI.restart_logger/0
    (mix 1.10.0-dev) lib/mix/cli.ex:82: Mix.CLI.run_task/2
    (elixir 1.10.0-dev) lib/code.ex:912: Code.require_file/2

So the first thing to note is that the log level :warn is deprecated, but is there also a new way to configure the log level?

Trying level: :info or level: :warning produce a similar warning, but no match error, and logging seems to work as usual.

4 Likes
4

Yeah, it seems like there is first bug :wink: Thanks

The point is that :warn used by Elixir Logger is now :warning form the Erlang, but there should be translation from old format to the new format. This was done, but in the meantime we have changed code a little to provide given message, and the translation perished. Will provide fix in a moment.

5 Likes
5

Thank you! This was bugging me in Rails apps for a long time. Why would you set the debugger level to warn if the output level was WARNING…

I think this is a very nice addition, but for my own sake, can you make sure to notify AppSignal about this? Maybe they already know, maybe they don’t care… I just don’t want to end up with unnecessary errors on that platform.

Thank you very much for everything (even though I curse you for introducing drab, no fun upgrading a phoenix app)

EDIT: as @hauleth has made clear, I mistook him for the creator of drab. @grych . Really sorry about the mix up, ignore what I said about drab.

2 Likes
6

They do not need about it, as the API is backward compatible, so if they are registering their own Logger backend (Elixir one) then nothing will change. They would need to use Erlang handler instead, but currently writing them isn’t so straightforward as Elixir ones (you need to prevent overload on your own, as Erlang logger do not handle it for you).

I do not get that as I haven’t worked on drab, I didn’t even used it even once in my life.

7

Oh, so sorry! your avatar looks like the other one on my tiny laptop screen… Really sorry, I mistook you for someone else.

1 Like
8

They provide a plug for Phoenix, and modules to do your own error messages, I was just wondering if they might be affected by this :slight_smile:

But you know what, I will shoot them a message, maybe they can improve their logging based on this :smiley:

1 Like
9

Very excited about this. Thanks for all your work!

I’m curious what approach you have in mind for structured logging. So far I’ve been doing it this way:

  • At the call site, pass structured data via metadata:
      Logger.log(level, "Processing request",
    method: conn.method,
    path: conn.request_path,
    ...
  )
  • Define a custom formatter which takes all metadata:
    config :logger, :file_log,
  path: "app.log",
  level: :info,
  format: {MyApp.Logger, :format},
  metadata: :all
  • In the formatter, generate JSON, roughly like:
    def format(level, message, timestamp, metadata) do
 %{
    "timestamp" => format_timestamp(timestamp),
    "level" => level,
    "message" => IO.iodata_to_binary(message)
  }
  |> add_metadata(metadata)
  |> Jason.encode!()
end
    where add_metadata reads each key/value pair from metadata, converts the value to a printable representation, and adds it to the event map, similar to Honeybadger.JSON.

It works, but it’s not ideal - we had to reimplement functionality from the default formatter, for instance formatting time or converting PIDs to strings. OTP reports also can’t be structured, because they’re a string blob by the time they reach the formatter (not a huge deal though).

Could we achieve JSON logging more easily with the new backend, or with future development?

3 Likes
10

Partially yes, and yes.

Elixir’s Logger currently do not expose API for structured logging, but as these two are integrated, you are free to use Erlang logger API directly, which does support that. The API is pretty simple and in your case it would be:

:logger.log(level, %{
  method: conn.method,
  path: conn.request_path,
  …
})

The problem with this approach is that you still do not have direct access to the report (as it is called) in Elixir backend nor formatter, as these will receive message already changed to string. So in this situation you have 2 possible approaches:

  1. Use Erlang handlers directly with whatever formatter you like
  2. Define your own translators for Elixir, which have direct access to the report and you can modify them as you please

The 1st approach is IMHO much more foolproof and should be simpler to manage in future (unless you are using custom backend for Elixir, but from what I see, you log to disk, and Erlang logger provides 2 handlers for that logger_std_h and logger_disk_log_h).

2 Likes
11

We can test it, especially if opencensus trace_ids will appear here.

12

It will, as this was partially the reason to do such. This integrates the Erlang and Elixir process metadata, so it will be perfectly reasonable and possible to set such data in one place only.

13

and those Logger patches can be removed too? can this help to collapse Logger and lager?

14

Yes, Lager automatically attaches itself to the logger as a backend, so it will not be longer needed for any compatibility layer. What is more, such libraries will be harmful, as can cause duplicated logs or infinite logging loop.

15

Just to check, but I think the answer is “yes”: You can use Elixir code to write these Erlang logger handlers?

16

Elixir modules play by the same rules as Erlang modules, so yes, you can. However right now it is a little bit harder to do so as Erlang handlers are required to protect themselves against overload instead of providing system solution like Elixir does. So for now I would say that it is safer to write custom formatters rather than custom handlers.

And if that wasn’t clear, all “old” handlers still work, just if this land it would probably be softly deprecated to use them (probably not immediately, but sooner than later).

17

So we can replace LoggerFileBackend with logger_disk_log_h? What does that look like?

18

Partially yes. Configuration via kernel application isn’t directly supported (yet?), but you can run:

:logger.add_handler(:disk_log, :logger_disk_log_h, %{config: %{file: 'test.log'}})

Somewhere during the startup of the application. But remember that you can use also logger_std_h if you do not need fancy file rotation or other things as that handler also supports output to file.

1 Like
19

Alright, I was trying to replace my logger config with it and failing.

Will there be a way to configure logger_std_h directly from the regular logger configuration in 1.10 or will we still need a custom backend?

20

There should be a way to do so, the discussion how to handle that is there.

1 Like