Logger improvements

[hauleth]

• [x] Convert usage of :error_logger to :logger
• [ ] Migrate :console backend to be defined as a formatter for logger_std_h - this will allow to use the same format as Elixir is using for other handlers as well (requires erlang/otp#2491 - OTP 24+ and erlang/otp#2523 - OTP 23+)
• [ ] Only attach built-in Logger.Handler if there will be backends (depends on the above)
• [ ] Do not depend on logger:macro_log (requires https://github.com/erlang/otp/pull/2721 - OTP 24+)
• [x] Expose API for module and application level verbosity control (#9793)
• [x] Expose and document all of Erlang built-in logger levels (#9791)
• [x] Add support for passing map as a "message" to the Logger macros to allow structured logging (needs to be fully discussed before) (#9797)
• [x] Use time field from metadata instead of generating new timestamp (#9772)
• [ ] Make Logger.Formatter works also as a Erlang's logger formatter for use with Erlang's logger handlers
• [ ] Make translators a step in Logger.Formatter.format/2 instead of running them independently
• [ ] Document usage and configuration of Erlang's handlers with Elixir's Logger
• [ ] Add API to set the global metadata (OTP 24+)

[josevalim]

Note: don't send PRs for those yet. We will probably wait until the Logger integration stabilizes a bit before going all in.

[hauleth]

Issues to track:

• ~~erlang/otp#2444 - accept binaries in entries using format~~
• ~~erlang/otp#2442 - allow ignoring messages from within the log function (by returning :ignore)~~ no longer relevant as it was removed from Elixir as well
• ~~erlang/otp#2491 - allow using binaries in :logger_formatter template to simplify integration with Elixir~~

[hauleth]

@josevalim I slowly start working on these, so it would be at least partially ready for 1.11.

[josevalim]

Perfect, the earlier the better!

[hauleth]

~~Another one PR to core erlang/otp#2523 - this one is to fully support :device option in logger_std_h.~~

[vans163]

Can this get tagged on too, https://bugs.erlang.org/browse/ERL-1159.

Basically to not push up the REPL prompt on Logger outputs.

iex(2)> :erlang.spawn fn()-> Process.sleep(1000); IO.puts "hi" end   
#PID<0.108.0>
hi
iex(3)>

iex(3)> :erlang.spawn fn()-> Process.sleep(1000); Logger.debug "hi" end
#PID<0.112.0>
iex(4)> 
16:07:31.101 [debug] hi

Notice how iex(4)> flushes first then the debugger process prints. Vs in the IO.puts case, its synchronized.

[josevalim]

Hi @vans163, because the issue happens in both Erlang and Elixir and are not specific to the integration, it should be rather directly tracked in Erlang issues tracker. Thanks for pointing it out though!

[hauleth]

Traditionally in most languages the stdout is buffered and stderr is not, this follow libc "standard". Additionally Elixir's logger use :user as a default device instead of :standard_io and that can be an issue here. AFAIK the problem is unsolvable in general case as there is no "registry" of all defined io:device/0s (any registered process can be a device). And as :user writes directly to 0 and is not synchronised in any way to :standard_io (I am no IEx expert, but I assume that it uses :standard_io not :user as a IO device).

[vans163]

@hauleth I think this PR https://github.com/erlang/otp/pull/2523#issuecomment-581790305, would allow one to easily set standard_io as the output device in logger? Probably remedying this?

Then OTP error reports (like a crash report for a gen_server [also causes this]), would still hit that same logger right, and go to standard_io too?

EDIT: Actually it seems you can add standard_io already, I think i understand what you mean :standard_io != :user.

[hauleth]

Not really, Erlang (as you have spotted) uses standard_io by default, it is Elixir that is using user. And as I said, it is not possible to do anything about it. If erlang/otp#2523 will be merged then it will be possible to use the same device for logger and IEx and then it will be synchronised, otherwise there is unfortunately no solution for You. Currently you can try with:

config :logger, :console,
  device: :standard_io

And check if the error is still there. If not then it is exactly what I have said, and it is not a bug.

[vans163]

When I set it to standard_io like how you show it, I get no output at all.

[josevalim]

Hi @hauleth! :wave: This is just a heads up that we are about 45 to 60 days before the release candidate for Elixir v1.11. Therefore, if there is anything you believe should be included in Elixir v1.11, please let us know so we can coordinate it properly. Thank you!

[josevalim]

I believe the first two pending tasks here require Erlang/OTP 23. So I guess we have to wait until Erlang/OTP 23 is the minimum required version? If so, maybe we should merge this with #9603?

[hauleth]

@josevalim I didn't have much time to spare to work on remaining 2 issues. I will try to make it a thing in 1.12 after I release enough library which is extraction of logger_olp form the kernel.

[hauleth]

IIRC these do not require OTP 23, but the problems can be for example with formatter and "compile" step, which is not present in Erlang's formatters and which is used in Elixir's Logger formatter (to change binary format into something that will be easier to digest later).

[josevalim]

@hauleth I see. I guess the first task can be broken in two. One is the formatter and the other is the removal of :console. My understanding is that Elixir's console logs to user and allows the device to configured but this is only available in Erlang/OTP from 23+, so we can't remove :console before - which means we can't do the second task either. Using the Erlang formatter for :console could be a nice benefit for re-use though (and we can list it as a task on its own).

[ymtszw]

Hi, I'm deeply apreciated on structured logging, and I assume it is introduced in Elixir 1.11 partially. This is a query for clarifying current status:

• Currently, while using :console backend (which we do for our container-based deployments), structured reports are automatically converted to string representations of key-value pairs (e.g. "foo: 100"), and it CANNOT be customized by means of custom formatter. Is that right?
• And what is the recent plans around :console backend? The above comments read that there's a plan to alter the implementation of stdio loggers.

As a background, we are using :console backend and custom JSON formatter to emit logs to containers' stdout, and collecting / forwarding them into JSON-based log consumer service (i.e. AWS CloudWatch). I'm asking this to know if our current approach still holds in coming Elixir versions.

[josevalim]

That’s right. We kept the current format for backwards compatibility. We have plans to have new backends that can handle the structured logging as is. Right now, your best option is to implement an Erlang logger handler.

[hauleth]

Yes, currently there is no way to format the reports (structured messages) in Elixir formatter, however, you can do it Elixir translator. It will require some workarounds to not format everything, but in general should be possible. However as @josevalim said, it would probably be better to implement it as Erlang logger handler. I am working on creating enough library for providing last missing piece from the Erlang logger handler (which is overload protection) if you need something like that.

[ymtszw]

Thank you two for the clarification!

Quick search gave me this forum post: https://elixirforum.com/t/how-do-i-use-erlang-flatlog-in-a-mix-project/32697 Regarding to implement our logger handler as Erlang logger handler. Is this still a viable starting point?

Or, for now I should rather try on Elixir translator path?

Either way, my intention is (a) handle structured reports and emit them as JSON objects (if possible right now), while (b) easing the foreseeable migration when stdio logging is rearchitectured.

[hauleth]

Whatever works for you. If you do not care, or you will handle all formatting on your own, then I would go with Erlang logger formatter for logger_std_h. The only problem there is that you will need to configure your logger in application startup, as Elixir do not support configuring it via config/config.exs in development. So you will end with different logger implementations in development and production. If that suits you, then you can go that way. Implementing formatter for Erlang handler is very straightforward and I really encourage you to check that out, as I see it as a great simplification over the Elixir approach.

[josevalim]

@hauleth this is the "document". :D I want to see what need to update and tackle. :)

[hauleth]

@josevalim I have added few points. Maybe we should split this issue into set of smaller ones that will describe each of the needed tasks, and then join them using GitHub Project instead of having one issue that is "catch'em all".

[josevalim]

@hauleth if they are not being acted on, I would prefer to keep them here to avoid "polluting" the issues tracker. We can always fork out when there is a plan to move forward. :)

[josevalim]

And thanks for the additions, they look great! :+1:

[hauleth]

Added more stuff. Some of them are ready to be done in OTP 24+ (migration from :console to :logger_std_h) and added links to Erlang issues in few others.

[polvalente]

@hauleth Me and a colleague noticed that between Elixir 1.12 and Elixir 1.13 a change was introduced in which Logger.warning now prints "[warning]" instead of "[warn]" as the log level metadata. This seemed to be an intentional change, from what the diff between 1.12 and 1.13 shows.

However, I could not find any mention of this in the Elixir 1.13 changelog. Did I miss something too obvious? This isn't too critical, but this could potentially break monitoring stacks which depend on the log level string.

PS: Sorry if this isn't the proper channel to ask this. Please point me to the proper one if this is the case!

[hauleth]

@polvalente it is not my doing, but it sounds like bug, so you probably should create separate issue for that. The formatter output should not change as it may be breaking change (as you have noted).

[josevalim]

We changed "warn" output to align with the new log levels and Erlang/OTP. I will update the CHANGELOG.

[tsloughter]

Is nested metadata supported by Elixir Logger?

I almost missed this when about to merge https://github.com/open-telemetry/opentelemetry-erlang/pull/394 which uses nested logger metadata. In the example using Erlang formatter for the default handler it looks like:

 {otel_span_ctx, ["trace_id=", [otel_span_ctx, trace_id], " ",
                            "span_id=", [otel_span_ctx, span_id], " "], []},

So it only has to check if otel_span_ctx key exists and if it does it includes the trace and span id, if not it includes nothing [].

The metadata looks like:

logger:update_process_metadata(#{otel_span_ctx =>  #{trace_id => io_lib:format("~32.16.0b", [TraceId]),
                                                     span_id => io_lib:format("~16.16.0b", [SpanId]),
                                                     trace_flags => case TraceFlags band 1 of 1 -> "01"; _ -> "00" end}}).

It was first noticed by @btkostner who didn't see the metadata when using :all https://github.com/open-telemetry/opentelemetry-erlang/pull/394#issuecomment-1139085945 but does when using his own Logger backend.