search

qos-ch / slf4j

Simple Logging Facade for Java
http://www.slf4j.org
MIT License
2.34k stars 990 forks source link

Allow to pass in a "formatted message" via SLF4J LoggingEvent (in addition to "message" field) #437

Open neeme-praks-sympower opened 1 week ago

neeme-praks-sympower commented 1 week ago

Context

Logback ILoggingEvent (source) has two important fields / getter methods:

This distinction is useful -- for example, we use this to aggregate log messages and this works fine when we call SLF4J API directly.

However, we are now migrating to Kotlin and have started using kotlin-logging (Kotlin logging library on top of SLF4J). Kotlin logging supports constructing log messages with Kotlin-native String interpolation, like this:

logger.debug { "Some $expensive message!" }

This results in the log message "template" merged with log message arguments too early. I have a proposal for kotlin-logging to support passing in the log message "template" so I could implement a Kotlin compiler plugin that would collect the template from Kotlin source code and would pass it along with the formatted message.

Issue

Even if I pass the log message template to kotlin-logging, it cannot pass it on as SLF4J does not support such scenario -- SLF4J LoggingEvent does not have a field for this. I guess SLF4J was designed to be the user-facing API and did not have a need to expose such low-level concepts in the API.

Proposal

Introduce a new field in SLF4J LoggingEvent that would contain the (pre)formatted log message. Then the logger implementations can use it like this:

This will make possible for me to implement something on top of KLogger to fill that field properly.

ceki commented 1 week ago

@neeme-praks-sympower Thank you for this report. Have you looked at SLF4J's fluent API?

neeme-praks-sympower commented 1 week ago

Have you looked at SLF4J's fluent API?

No, where can I find it? But I suspect fluent API would just be a user-facing wrapper API, underneath it would still use LoggingEvent from SLF4J SPI, no?

ppkarwasz commented 1 week ago

No, where can I find it?

The fluent API is documented in the SLF4J manual.

But I suspect fluent API would just be a user-facing wrapper API, underneath it would still use LoggingEvent from SLF4J SPI, no?

The way the fluent API works depends on the implementation, but you'll be able to recover the format string anyway:

neeme-praks-sympower commented 1 week ago

Thanks for the explanation.

The problem in my case (as I tried to explain in the original issue description) is that kotlin-logging does not delegate the formatting of the final log message to SLF4J -- it builds the final message itself and then passes that final message into SLF4J API as the "format string". This would not be a problem unless we want to use the format string inside the backend logger implementation (Logback) in order to aggregate log messages.

How it works currently:

sequenceDiagram
    participant user-code
    participant kotlin-logging
    participant SLF4J
    participant Logback
    user-code->>kotlin-logging: logger.debug { "Some $expensive message!" }
    kotlin-logging->>SLF4J: SLF4J LoggingEvent with<br/>message="Some expensive-value message!"
    SLF4J->>Logback: SLF4J LoggingEvent with<br/>message="Some expensive-value message!"

How I would like it to work:

sequenceDiagram
    participant user-code
    participant kotlin-logging
    participant SLF4J
    participant Logback
    user-code->>kotlin-logging: logger.debug { "Some $expensive message!" }
    kotlin-logging->>SLF4J: SLF4J LoggingEvent with<br/>message="Some expensive-value message!"<br/>messageTemplate="Some $expensive message!"
    SLF4J->>Logback: SLF4J LoggingEvent with<br/>message="Some expensive-value message!"<br/>messageTemplate="Some $expensive message!"

This actually differs from my original proposal -- I suggested to introduce formattedMessage field but I just realised that introducing a messageTemplate field is better for backwards compatibility.

ceki commented 1 week ago

@neeme-praks-sympower You have obviously spent some time thinking about this problem.

The org.slf4j.Logger interface contains new "fluent" methods such as atTrace(), [atDebug()](https://www.slf4j.org/apidocs/org/slf4j/Logger.html#atDebug()), atInfo(), atWarn() and atError(). These methods return an instance of LoggingEventBuilder which build a LoggingEvent instance piecemeal.

If the calling logger is disabled for the given level, the returned object will be the the unique instance of NOPLoggingEventBuilder, whose methods, as the NOP prefix would suggest, perform no operation.

In the case the logger is enabled for the given level, the returned instance is often of type DefaultLoggingEventBuilder

Please have a look at the code of LoggingEvent and LoggingEventBuilder before further discussion.

In particular note the addArgument(), addKeyValue(), setMessage() methods as well as the variants of these methods taking an instance of Supplier as an argument. Also note that in LoggingEvent interface, the message field is the non-interpolated template. There is no formattedMessage at all.

neeme-praks-sympower commented 1 week ago

The fluent API is nice but not really relevant as in the end it is just a convenience wrapper around SLF4J LoggingEvent.

Also note that in LoggingEvent interface, the message field is the non-interpolated template. There is no formattedMessage at all.

Exactly, that is my issue. In order to achieve what I need, there needs to be two fields:

Basically, the current SLF4J API assumes that SLF4J is ALWAYS responsible for interpolating the message template and producing the final log message. But in the case of kotling-logging, this is not the case: kotlin-logging relies on Kotlin built-in string interpolation in order to produce the final log message. As a side-effect, the original non-interpolated message template is lost. My goal here is to add a possibility to SLF4J API (LoggingEvent interface) to pass in the original message template in case the message field contains the final (interpolated) log message.

Possibly the main source of the confusion arises from the fact that the semantics of the message field changes slightly in the process.

Currently

Message field contains the non-interpolated template. But it is also ok to pass in the final interpolated log message (then it just does not contain any variables).

My proposal

Introduce a non-interpolated messageTemplate field in LoggingEvent. As a side-effect, message field is assumed to ALWAYS contain the final interpolated log message.

By default (for backwards compatibility), logger backends (e.g. Logback) can continue to use the message field as before.

Case of Logback ILoggingEvent:

However, in some cases (I'm interested in Logback case), they can take advantage of the new field and skip interpolation.

Case of Logback ILoggingEvent:

ppkarwasz commented 1 week ago

@neeme-praks-sympower,

The problem in my case (as I tried to explain in the original issue description) is that kotlin-logging does not delegate the formatting of the final log message to SLF4J -- it builds the final message itself and then passes that final message into SLF4J API as the "format string". This would not be a problem unless we want to use the format string inside the backend logger implementation (Logback) in order to aggregate log messages.

As far as I can see, kotlin-logging has also a fluent API:

logger.atWarn {
   message    = "foo $bar"
   cause      = exception
   payload    = buildMap(capacity = 3) {
     put("foo", 1)
     put("bar", "x")
     put("obj", Pair(2, 3))
   }
}

If they agree to extend KLoggingEventBuilder to accept an arguments parameter, you could write:

logger.atWarn { message = "foo $bar" }

and rewrite it via a compiler plugin into:

logger.atWarn {
  message = "foo {}"
  arguments = arrayOf(bar)
}

Since the fluent API of kotlin-logger ends up calling the fluent API of SLF4J, you would be able to have the correct LoggingEvent.getMessage() value.

@ceki,

Also note that in LoggingEvent interface, the message field is the non-interpolated template. There is no formattedMessage at all.

Could you add this requirement and other implicit requirements to the Javadoc? For example, while it is clear to me that the objects in LoggingEvent.getArguments() are to be considered lazy strings (and Object.toString()) will be applied to them, I don't entirely understand what kind of objects are allowed in LoggingEvent.getKeyValuePairs(). My guess is that implementations should at least be able to handle in a special way the OpenTelemetry any types (i.e. primitives, strings, any[], List<any> and Map<String, any>) and can stringify the rest.

It is also not clear to me how implementations should handle both the presence of a message and key value pairs. Are implementations required to handle them separately or is message a special key value pair with key message?

neeme-praks-sympower commented 1 week ago

If they agree to extend KLoggingEventBuilder to accept an arguments parameter, you could write:

logger.atWarn { message = "foo $bar" }

and rewrite it via a compiler plugin into:

logger.atWarn {
  message = "foo {}"
  arguments = arrayOf(bar)
}

Since the fluent API of kotlin-logger ends up calling the fluent API of SLF4J, you would be able to have the correct LoggingEvent.getMessage() value.

Yes, this could be one way of solving this.

The positive side of this solution is that it would not require any change in SLF4J API.

The negative sides are: