Call for testers: new Elixir Logger backend

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.

Yeah, it seems like there is first bug 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.

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.

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.

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

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

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

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?

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).

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

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.