KLogger does not properly populate SLF4J/Logback ILoggingEvent "message" field

[neeme-praks-sympower]

Context

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

• message - contains the message template (e.g. "Hello {}!")
• formattedMessage - contains the final formatted/merged log message (e.g. "Hello world!")

This distinction is useful -- for example, we use this to aggregate log messages.

Issue

KLogger relies on Kotlin string interpolation and as a result, the message field contains the same formatted message as formattedMessage, breaking the possibilities for aggregation.

Proposal

Introduce a new field in KLoggingEventBuilder that could contain the log message template (e.g. "Hello $variable!"):

• in case this field is filled, it is passed as-is to SLF4J LoggingEvent.message field and the formatted log message is passed to LoggingEvent.formattedMessage (see also Allow to pass in a "formatted message" via SLF4J LoggingEvent (in addition to "message" field) qos-ch/slf4j#437).
• in case this field is not filled, the current behaviour is followed (using the formatted message for LoggingEvent.message and leaving LoggingEvent.formattedMessage empty).

This will make it easier for me to implement something on top of KLogger to fill that field properly (I'm thinking of implementing a Kotlin compiler plugin).

[github-actions]

Thank you for reporting an issue. See the wiki for documentation and slack for questions.

[oshai]

Can you please provide some more info?
You mean that the un-formatted message will be added by the compiler plugin? if so, sounds like an interesting idea. In the past I thought of using a compiler plugin to add line numbers, file name, etc'. But never implemented it.

[neeme-praks-sympower]

un-formatted message will be added by the compiler plugin?

Exactly.

In the past I thought of using a compiler plugin to add line numbers, file name, etc'

Also possible, yes.

[oshai]

ok, would you like to send a PR for that or let me do the proposal?

[neeme-praks-sympower]

I'm mostly interested in the unformatted message. In case you have broader scope in mind then it is probably better if you come up with a proposal.

[oshai]

I suggest that you'll do the initial PR for the unformatted message (maybe call it rawMessage) and I will add on top another PR. Make sense?

[neeme-praks-sympower]

I just understood that the ILoggingEvent is actually part of Logback and SLF4J LoggingEvent also needs to support propagating the formatted message. So I submitted an issue for that: qos-ch/slf4j#437

[neeme-praks-sympower]

One proposal from SLF4J developers (the original comment):

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.

What do you think about this change?

[oshai]

Do you know of a way to make it accessible only to the plugin? Can the plugin work with private members?

[neeme-praks-sympower]

Do you know of a way to make it accessible only to the plugin? Can the plugin work with private members?

The compiler plugin would be manipulating the (user-written) code that calls kotlin-logging API -- it does not manipulate the kotlin-logging code. So, the API that it would call would need to be public -- users can also call the same API themselves.

Some options, from the top of my head:

• Extend the current API and allow SLF4J-style variables next to Kotlin-style variables (as suggested by SLF4J developers)
• Introduce a new (internal and hidden) API, discourage users from using that.

I would prefer the first option.

[oshai]

I would like to avoid the first option. It will also cause confusion for users in other platforms (not jvm).
How about calling logback directly not via slf4j? We have something similar for jul.

[neeme-praks-sympower]

How about calling logback directly not via slf4j? We have something similar for jul.

That sounds interesting, I'll investigate that option. Any pointers to get me started faster?

EDIT: I think I found it: https://github.com/oshai/kotlin-logging/tree/master/src/jvmMain/kotlin/io/github/oshai/kotlinlogging/jul

[oshai]

It's decided via system property here: https://github.com/oshai/kotlin-logging/blob/master/src/jvmMain/kotlin/io/github/oshai/kotlinlogging/internal/KLoggerFactory.kt

And the impl is here: https://github.com/oshai/kotlin-logging/blob/master/src/jvmMain/kotlin/io/github/oshai/kotlinlogging/jul/internal/JulLoggerWrapper.kt