MetadataLogger: logging with metadata (+ tesla / plug middleware)

As you correctly pointed to my post on the forum with call for testers I need to make few statements:

• In near future (when the new logger implementation stabilises) we will add proper structured logging to the Elixir’s Logger where metadata and “log message” (or, as called by Erlang, report) will be possible without any wrappers (#9465)
• There is plan to deprecate “old” backends (and naturally formatters) in favour of using Erlang’s handlers and formatters API directly (#7928)

Additionally your metadata_logger_plug is currently more or less possible via Plug.Telemetry API, which I believe is currently more standardised and commonly supported (ex. Phoenix.Logger uses that).

However, nice work and I really appreciate idea of bringing structured logging to Elixir.

Thanks! I know there are lots of work going on logging and telemetry (which can be used for logging as well).

Here are my takes:

Log formatter will remain - just in different form: seems like new erlang logger (21.1) has log_formatter and Elixir is planning to use same mechanism so that elixir and erlang use same log event, and leverage same logging backend (via passing handler_config)

Metadata will be a map - I think this is the right way to go, as erlang already uses map ref (and it’s planned in #7928)

Passing map as a message is planned but it won’t invalidate use of metadata - passing a map as a message is planned in #9465. However, I see metadata is for scope-based while map message is for per message - and I found both are needed when I’m using them.

Note that this can be done even in the current Elixir if you use formatter taking a map message See this PR I just wrote…

instrumentation logging via :telemetry - I really like that idea! Plug.Telemetry was added after I wrote this middleware I created issues: for plug and for tesla

I am fully aware of the implementation and future plans, I made both of them

Yes, but the plan is to make it Erlang logger formatter, as you have noticed.

Internally, yes, from the user viewpoint, no. This is required for the compatibility. So in Elixir 1.10 it will be changed before returning in Logger.metadata/0.

Yes, as metadata is for something completely different. Using your example in metadata_logger_plug the status, body length, and response status should be part of the report, not metadata. Metadata is more about, well, meta data like: version, log position, module, function, application name, etc.

Well, partially. It will work for that particular formatter, but in general it will fail (also Dialyzer will complain) as you break contract about type of the accepted data. So that single formatter will work (because it relies on undefined behaviour), but any other will fail, and this will fail with parsing Erlang reports, as these are handled before these end in your translator.

I think we’re pretty on the same page! Thanks a lot for follow-ups

I created a placeholder issue

Note on “metadata” being metadata.

That’s right for plug case (I’m putting them into metadata only because it’s only places I can put there for now).

However, please note that applications often need process-scoped logging data - such as plug request id - to group log messages with them later. For example, as I put them in (elixir) logger metadata (which is set in process), I can easily see all logs for a plug request.

Do I need to pass that “request id” to all functions which may produce logs? I don’t think that’s practical - and I believe that’s perfect use case of process-level information. As logger metadata is process-level - I’m just using that for process-level data.

Unfortunately, that leads to mix of runtime/language-specific metadata with application data - but Erlang itself even use metadata to carry not only event-specific info (e.g. file, line) and some configuration (e.g. report_cb)

Or do we want separate set of funcs and keep them separately and do not mix “metadata” of runtime and “process-level application data”? That’s possible - but I don’t think the current logger metadata discourage use of metadata for such use..

(I believe I brought up this somewhere, but I cannot remember..)

No, because request id isn’t part of the log message, it is part of the context for the log message. This is huge difference that I am pointing there. Erlang logger also makes these difference as there are separate. If I would need to define in short the difference then I would say:

• report/log message is about what happened (ex. Responded with OK 200 in 532ms (1 KiB) or %{http_response_code: 200, http_response_time: 532_000, http_body_size: 1024})
• metadata is about when and where it happened (line: 42, mfa: {Foo.Controllers.Users, :show, 2}, time: 1573853293025234000, pid: #PID<0.108.0>), additionally it will contain all “meta” stuff, like mentioned report_cb

So you do not mix metadata and log data, and you do not need to pass some metadata to each execution. How it is presented later is completely different thing. Some tools make it even more distinct (for example Grafana’s Loki) as metadata are indexed, so these shouldn’t vary too much to not bloat indices, while data is not parsed at all.

And this is a little bit of the problem, as such data do not belong to the “metadata”, as this is data (without “meta” part). Fortunately in near future this will change.