[RFC] Log Metadata

[waj]

This RFC raises some possible changes over the current API for log metadata (currently context), in particular with the concern of possible performance issues. I discused these points with @bcardiff over the phone and we decided to share some thoughts.

1. Split context and entry metadata

Currently the only way to write metadata values for each log entry is using the log context. This was intentional as the context was, in the initial design, understood as the "contextual" information for the current activity, and not data applicable only to the current log entry. So, for example, the current context could contain things like a "request ID", or the current user logged in. However, specific data like the duration of an operation, or the error code returned by a remote server, are not contextual values. So if someone wants to log that information as structured data and not just a text message, the current context must be replaced just for that log entry. Some work was done in #9146 to make that task easier, but with an extra performance impact.

Instead, for these cases, we propose that each entry has not only the current context metadata, but also some specific data we want solely that log entry to contain. If this data is provided as a named tuple, then this operation is very lightweight, avoiding having to modify the current fiber's context and merging with the existing values in that structure.

In other words Log::Entry will now contain not only context but also an optional data property.

This has one caveat that is there could be now some overlapping between the keys in the context and the entry data. I think the impact is minimal because the nature of the data on each case makes it rare to occur. We could either defer the compaction of both structures at the time the entries are processed by the backend, or it could be stored as separate entities.

2. DSL to set entry metadata

The design of the log APIs circle around the idea of minimizing the performance impact they have. So, it's really important to avoid executing operations that are later discarded because of the severity level currently configured for the process (or the log source).

Because of this, passing the metadata as arguments to the Log calls is not always a good option. Currently the text message is returned from a block due the same reason: skip executing interpolations if the result is then discarded.

The proposal is to extend this idea and let the block return either a String or a Log::Entry and provide some basic DSL to ease this task.

So, while this continue to be fully valid:

Log.info { "Some message" }

in case extra metadata is desired to be attached to the entry, a DSL object passed as argument could be used:

Log.info { |dsl| dsl.entry("Some message", foo: 123, bar: "More data with #{interpolation}") }

And actually, a more compact way is possible:

Log.info &.entry("Some message", foo: 123, bar: "More data with #{interpolation}")

Other options for this DSL could be added for other scenarios yet to discover.

3. Use symbols as metadata keys

During the first iterations of the log context design, the keys of the entries were symbols. This was later changed to be strings, in order to allow dynamic values unknown at compile time. I strongly think this is a mistake and we want to revert it back to just symbols. The reason is again, simple: performance. Even though we could optimize comparison between literal strings, if the API allows any string to be used as a key, there is always the possibility to affect the performance unnecessarily. The comparison of symbols will be always much better, and there is simply no reason to use unknown values for the keys. For example, if the request headers are desired to be stored in the current context, they header names themselves don't need be the keys of the context values. Instead, we could store the headers under a :http_headers key or similar.

[j8r]

I like the idea of metadata. However, not convinced by using Symbol for the sole reason of possible performance gains.

• With LLVM, we never know - this has to be benchmarked (I'd love to know :slightly_smiling_face: )
• If no real-world performance gain is noticed, String can be used
• Frameworks may manipulating Log configuration, this flexibility is always good to have (except for safety or noticeable performance)
• Accepting Symbol | String is also an option, if performance gain there is

[Blacksmoke16]

1. Split context and entry metadata

Monolog did essentially the same thing with context and extra.

I think it's deff a good idea to make the distinction. I'd probably just leave the two properties separate and let the formatter/backend itself define how to merge/render each key/value.

This does remind me of my processor idea. The fiber specific context definitely covers most use cases, like the requestID that are based on some value generated within an application. However something that is missing is handling static contextual data. For example, including git information within logged messages.

Currently to handle this you would need to write to Log.context in each entry point. A processor would just be something that accepts a Log::Entry to write some extra data to it regardless of where the entry originated.

Granted, maybe it's not common enough to worry about. Just a thought of mine.

2. DSL to set entry metadata

I think it depends on the data that is being included. Having multiple overloads to handle various contexts would be what I would opt for. I could see using the block version returning Log::Entry if the context is non trivial. But would it really be worth it if the values are static? E.x. Log.info(id: 17) { "Some Message" }. I guess you wouldn't need to allocate some strings but :shrug:.

[waj]

@j8r String could be optimized to make the equality comparison of literal values much similar to compare symbols (will never be the same anyway). But if the api allows just any string, that gain could fade away without noticing. If you are careful to always use literal strings, what's the difference anyway with symbols? It's just the syntax you don't like? That's a personal opinion anyway, because I like it, but I'm not using taste as the argument here. If that matters, I actually see strings mostly as a human thing: they represent text, and text is for humans. While symbols are for computers, with a human readable representation.

You mention log configuration by frameworks. I wouldn't add much more configuration to something that has to be simple and fast. I'd love to see any special configuration, useful in real life, that couldn't be solved unless strings are used as keys. You can always put the configurable value under a well known context key.

So far I only see reasons to use symbols, and none to use strings.

[waj]

@Blacksmoke16 we could consider adding processors if there's a real use case, but so far I didn't see much gain there. I pretty much prefer adding values to the top level context if needed, and avoid extra calls to be made for each and every log entry. That being said, couldn't you just write a wrapper backend that adds the extra information there?

Regarding the DSL, we also considered that option of having overloads for entry data, but the line is so slight and the intention here is to avoid unnoticed slowdowns. Also would you prefer to use two different calling conventions depending on the values? The change would be larger every time you want to add or modify a value that makes the call non trivial anymore. Anyway, I still don't discard that idea.

[RX14]

@waj I mentioned one reason in https://github.com/crystal-lang/crystal/issues/9159. Regressing expressivity for purely performance reasons, especially without a benchmark, doesn't seem sensible to me.

[asterite]

especially without a benchmark

It's not mentioned here, but @waj told me that a quick benchmark of Hash of String vs. Symbol has Symbol be about twice as fast.

[waj]

@asterite I didn't mention that because I'm not sure my benchmark is correct, so don't assume that performance gain 😆

@RX14 within point 3 I expressed the example you proposed and how I'd actually use it within contexts. So far I don't see any expressiveness penalty and so far in Crystal performance was always a reason.

[straight-shoota]

@waj When talking about performance optimization, I'd ask what exactly we're talking about. As far as I am a aware, an application usually generates log messages which are routed through the log framework to one or more backends. Does this process typically involve comparisons on context keys? I'm not aware of any. Maybe custom backends would do such stuff, but I can't picture a realistic use case. In most production environments (where performance matters), you'd ideally try to get the log messages out of the application's hot path as quickly and simple as possible and dump/delegate it somewhere (for example to specific log handling services). That usually involves serialization into some data format at which point we typically want strings anyway. There it shouldn't make a difference whether we're dealing with a string (whether it's a literal or dynamically allocated) or the stringification of an enum member.

[asterite]

Does this process typically involve comparisons on context keys?

If I understand things correctly, there's a Hash in the underlying implementation. When you insert stuff into it, the hash method is called on keys. For a symbol that's O(1) since it's just the underlying number given by the compiler at compile-time. With strings that's O(n) and depends on the string length together with some expensive calculations (the hash).

In fact in the compiler I would have liked to use something other than strings for identifiers and such, because then you can compare by identity. I believe every other compiler does that.

[waj]

@straight-shoota for this analysis, forget about backends. Of course the serialization of the entries is some orders of magnitude above in terms of performance. But I expect that to be asynchronous eventually. I'm just thinking about the penalty involved in adding logging to a piece of code. And trying to minimize the impact that could have to reduce the possibilities of logging less because of that. The comparisons happen every time you set values to the context.

[straight-shoota]

But the purpose of your metadata proposal is to reduce the frequency of context merging. External context which is not specific to an individual log message is more stable and won't change as often. So it naturally has less impact and at that point I'm not sure how much a performance optimization would actually be worth.

[RX14]

Wait, are we only talking about enforcing symbols-as-keys at the top level of context? I wasn't clear on that before. You can do Log.context.set(foo: {"whatever" => "baz"}) still?

[waj]

@RX14 of course!

[RX14]

I think that's where the major miscommunication came in then. I'm still not 100% on this change, but it's certainly reasonable.

Points 1 and 2 are fine to me.

[waj]

Ok, let's disregard point 3 for now. It's also true what @straight-shoota says that the impact is reduced with the addition of entry metadata. I'll perform some benchmarks and come back if necessary with fine tuned info.

[straight-shoota]

\1. and 2. definitely sound good! Regarding the DSL, I'd suggest emit as method name instead of entry: Log.info &.emit("Some message", foo: 123, bar: "More data with #{interpolation}")

[Blacksmoke16]

Thoughts on having overloads similar to #9152? Could make it simpler using only named argument/namedTuples and splat those into an entry/emit call within the block.

Having a simpler API for trivial arguments would be nice. I'm a bit skeptical that scalar/primitive arguments would cause that big of a performance impact to require them to go in the block directly.

[asterite]

@Blacksmoke16 the problem is that once you introduce a non-lazy API, people will use it because it's simpler. My personal preference is to just have a lazy API, even if it's longer or uglier.

[bcardiff]

I'm implementing the DSL and found an ambiguous corner when attaching exceptions.

Until now we have Log.fatal(exception: ex) { "Ooops" }.

Maybe to keep less options we can move that to Log.fatal &.entry("Ooops", exception: ex)

Otherwise it is not clear (or desireable to allows the user write): Log.fatal(exception: ex1) &.entry("Ooops", exception: ex2)

Should we drop Log.fatal(exception: ex) { "Ooops" } in favor of single way to emit entries with structured information?

Log.fatal &.entry("Ooops", exception: ex)
Log.fatal &.entry("Ooops", exception: ex, data: aMetadataObject)
Log.fatal &.entry("Ooops", exception: ex, a: 1)

[waj]

But exception is not part of the metadata, so that syntax look a little bit ambiguous.

I'm not sure about dropping the block syntax for strings. What about a fluent interface?

Log.fatal &.entry("Ooops").with_exception(ex).with_data(a: 1)

[bcardiff]

Too verbose IMO

If the syntax is too ambiguous we can go in the route of forcing always exception / data keys.

Log.fatal &.entry("Ooops", exception: ex, data: {a: 1})
Log.fatal &.entry("Ooops", exception: ex)
Log.fatal &.entry("Ooops", data: {a: 1})

The ambiguity with attaching exception still holds. And it can be kept. Forcing the user to do the following to attache data and exception is too ugly to me:

Log.fatal(exception: ex) &.entry("Ooops", data: {a: 1})

[straight-shoota]

I agree with @waj that the exception should probably not be treated as a regular data value. It doesn't have any cost attached, so there's not much benefit from adding it in the block. So I'd go with assigning the exception property always as an argument on the log method. And I'd definitely keep the API for simply returning the log message from the block. That's nice and concise. And in many cases you won't need to attach any data. We shouldn't force using a more complex API for these simple and common use cases.

Log.fatal { "Ooops" }
Log.fatal &.entry("Ooops")
Log.fatal &.entry("Ooops", a: 1)
Log.fatal(exception: ex) { "Ooops" }
Log.fatal exception: ex, &.entry("Ooops")
Log.fatal exception: ex, &.entry("Ooops", a: 1)

[bcardiff]

Ok, I'll go on that route. exceptions in the main method. data as plain keyword arguments on yielded method.

[paulcsmith]

I feel super strongly about this and LOVE it. This would remove one of the biggest things I needed for Deter, local context/data: https://github.com/luckyframework/dexter

I also love the syntax. Short, concise, readable, and since it is still a block it won't run if it won't be printed ❤️

Can I just ask for one tiny addition? Letting users leave off the message and just set it to an empty string if ommitted. Most of the logs in Lucky and my personal apps are key/value data without a particular message. The formatters in Dexter and Lucky are set to ignore empty String messages, so if I could use this Dexter barely even needs to exist except for the type-safe config helpers and formatters. That'd be great!

For example:

# Sets the message to an empty string (or I'd prefer nil, but that's a whole new discussion lol)
Log.info &.entry(query: query, query_args: [1, 2, 3])

I have no preference on symbol or string keys. I personally always use symbol and if symbol is faster that sounds awesome.

[jkthorne]

Quick question about the syntax. Can the block return multiple objects? If so could we get rid of the &.entry syntax?

Log.info { "Message", {foo: "bar"} }

Here is an example of multiple returns. https://play.crystal-lang.org/#/r/90cv

[bcardiff]

No, it can't.

The more similar would be

Log.info { { "Message", {foo: "bar"} } }

But I think that is to many {

The return statement allows you to avoid the { } for the tuple, but method { expr, expr } does not parse.

You can compare the following example:

• https://play.crystal-lang.org/#/r/90fc
• https://play.crystal-lang.org/#/r/90fd