Seriously, what do we do with logs in Elixir? There is seemingly no way to make them good both in dev and prod. This is especially noticeable in libraries, which often choose to simply not log.
In my new post I propose a solution and explain why telemetry isn’t quite it.
TL;DR: structured logging aka reports logging is a great way to make your logs programmatically accessible and thus customizable while still providing a preferred, terminal-friendly text representation
Good article buy I was surprised Syslog 5424 wasn’t mentioned at all. No need to come up with a format while there’s already a standard which includes both structured data and human-readable portion.
Well, TIL about RFC / syslog 5424.
I use a telemetry based logger in my libs (gen_mcp : gen_mcp/lib/gen_mcp/telemetry_logger.ex at main · lud/gen_mcp · GitHub , crown : crown/lib/crown/telemetry_logger.ex at main · lud/crown · GitHub )
I believe you should expand that part of the post, or make a follow post, because it’s the best solution (to me at least): it lets people enable the logs they want, and does not get in the way.
Hmm, I admit I don’t have a lot of experience with Syslog 5424, but I think it’s a format, right? Just like GCP or Datadog json-based formats? In that case, it’s not really relevant here, since I’m not proposing a new export format, but rather a way to write logs that will better accommodate any format. In general case, a running app can have multiple logging handlers: a default handler with default terminal formatter, an additional handler with json format and another one that sends errors to Sentry over HTTP. Reports are equipped to work well with all of them.
I touched this topic at the end. Telemetry doesn’t really solve this particular problem. In your library, you still have a handler that calls Logger.log with dynamic message and metadata, which is ok, but not perfect. If users were to customize logs, they would have to basically throw away all your efforts and do the work themselves. Telemetry just makes it easier to do.
You could totally use reports in your handler and that would make your logs even better!
I touched this topic at the end
I know and mentioned it 
Telemetry loggers like mine have advantages too, it’s opt-in, filtering by prefixes is easy and straightforward, and it’s telemetry, you are dispatching an event that can be logged, but can also be used for other purposes such as converting to OTel metrics.
But I don’t disagree with your post at all, actually I think it’s very interesting.
You could totally use reports in your handler and that would make your logs even better!
Yes! A basic telemetry logger could in addition call the logger with the whole telemetry metadata and report_cb instead of converting to a string. So users can attach the default logger and filter / reformat, or they can filter at the producer level (and still reformat).
they would have to basically throw away all your efforts and do the work themselves
This is a good thing in my opinion. It’s basic code that is really easy to write. Writing a filter is more or less the same level of effort, but attaching your own telemetry handler lets you start with a blank slate.
RFC 5424 is just the output format, not the approach to firing logs, as @martosaur pointed out. This format is also quite painful to use in many places, because you need to apply for Private Enterprise Number if you want to conform to it. And SD-DATA from RFC 5424 is more for metadata rather than message itself (there is difference, substantial difference, between these two).
TBH the same applies to report/structured logs. Telemetry is log dispatching mechanism (very primitive one), just focused mostly on metrics.
This feels very much in line with me favoring using exception modules (Example) to build exception messages from data – even though I myself am not the best in following that advice.
But besides the technical question there’s also the “what is worth logging and how do I decide on a severity” portion, especially when working on a library. Because if that one’s not right then people need to start filtering out logs and I personally prefer to work additive rather than logging stuff only for it then needed to be filtered. That’s what I personally struggle more with. Maybe that’s why I tend to debug in production using traces. I know they’re not useful when you cannot reproduce an issue, but when you can they’re just so much more flexible.
Edit:
I just looked at logger — OTP 29.0.3 (kernel 11.0.3). It seems like there’s also a arity 2 version, which would allow replacing the :io formatting with a custom to string formatting. That could be used to make this a bit more approachable from elixirs end.
That is why I am not much of a fan of Elixir’s default of Logger level set to :debug. Erlang which sets it by default to :notice is IMHO better one, as it (by default) filter more messages that are irrelevant to the user. It has slight disadvantage in development, but IMHO we should make defaults safe for production, not for development.
Anyway, I digress a little.
Actually it is the exact opposite. The reason for that is that when you use report_cb/2 then it is your requirement to ensure, that for example line length is preserved. If you use report_cb/1 it is left to the formatter to keep all that requirements.
I understood that. But it means :io.format is no the only possible option. I do agree with the blog post that this is quite the arcane formatting syntax, which I’ve never really seen favored by people using elixir. There could be alternatives still handling all those constraints, but using a different syntax for formatting.
I really can’t miss this opportunity to scream that Elixir logs have always been one of my biggest and most frequent rants. For all that is good about this language, logs are unforgivably horrendous 
I’d love if unstructured logs did not exist, ever. There’s not a single good usecase where structured logs plus a report_cb doesn’t win. I always create structured logs with a report_cb that formatters can optionally call if they want to create a user-friendly string from the structure, noting, “user-friendly” is forever a subjective opinion and should therefore be strictly optional and never overriding the actual structure, in case someone else wants to format things differently. And even then, the “user-friendly” string should not replace the structured payload. But then I’ve seen many libraries that, as soon as they see a report_cb field, replace the entire structure with the value of that report_cb, so I can’t even safely add my own callbacks either.
I’d also be more than happy if Logger just did not exist at all, for once erlang’s :logger is better at about everything. For example, how the Logger is configured always bites me, it’s all :logger under the hood but all the configuration is slightly different so it always takes me several rounds to configure the right thing (one example, handlers other than the default are configured under the application and with a few keys being named differently).
If there’s only one thing I wish to put out there and for every one to take, ranting aside, is to use structured logging, not optionally, not sometimes, but as the only valid way. I’d even make it enforced by the library and fail compilation otherwise 
PS: @PragTob has heard my rants so many times 
The problem is that Logger is older than :logger. If :logger would exist when Elixir was created, then it probably would always be just a thin wrapper around :logger with no separate configuration. But that was not the case.
It is now, but before 1.11 or 1.12 that was not the case (actually Logger was registering itself as :logger handler to process Erlang logs through Elixir’s backends).
So the whole mess is because of backward compatibility and the fact, that for a long time Erlang didn’t had any sensible logger. Before OTP 21 there was only error_logger module which was not general purpose logger, and if you wanted to have sensible logging in Erlang you needed to use lager. That is why Elixir’s Logger exists.
Another thing is that before OTP 24.2 there was no standard way to reconfigure logger while VM was already running (configuration of :logger happens in :init module that is ran before Elixir can even process its configuration). So each tool was doing the reconfiguration in their own, potentially incompatible, way.
Hooray compatibility, Raymond Chen would be proud of us.
I’m not a fan of report_cb/2 because of the issue grouping thing. report_cb/1 returns a tuple that conveniently represents static and dynamic parts, but with report_cb/2 those parts are already mushed together which makes it less useful.
And also there’s the part that @hauleth pointed out: with report_cb/2 it’s your duty to preserve line length and I for one have zero idea how to do it properly 
I’m not sure how useful this is by itself tbh. I see this purely as an implemenation detail of how :logger handles turning the information into text. I would never reuse those callbacks for anything else.
© Copyright Elixir Forum | Terms | Privacy & Cookies
