Can't get extra fields in json output without relying on deprecated methods

[sigmanil]

Hi, and thank you for maintaining an excellent library!

We have unfortunately run into a little problem:

We noticed that the support for writing log statements on the form log.error("Cake", StructuredArguments.keyValue("caketype", "chocolate")) (with net.logstash.logback.argument.StructuredArguments) has been deprecated. We use that style to include extra fields for json logging.

The replace-with in the deprecation creates a wholly different result. After some searching, we noticed the "atError" etc function that take a payload, and hoped they could be used to replace the old behaviour.

log.atError {
   message = "Cake"
   payload = buildMap {
      put("caketype", "chocolate")
    }
}

But while that does include the caketype/chocolate pair in the output for ordinary logging, it disappears when we use Json logging.

For a fairly minimal example, see the below files and the comments in main. The behaviour of atError seems to be opposite of the behavior of the old method, in that the old one doesn't include the extra field in "ordinary" logging, while the new one does - and vice versa when it comes to json logging.

Have I misunderstood what the payload argument of atInfo, atWarn etc functions are supposed to be used for? If so, how do we reproduce the old behaviour for including extra fields in json output without leaning on the deprecated method? (Or is this a bug?)

Thanks in advance for any hints or ideas, we're a bit stuck here. :-)

Main.kt

import io.github.oshai.kotlinlogging.KotlinLogging
import net.logstash.logback.argument.StructuredArguments

private val log = KotlinLogging.logger {}
object Main {
    @JvmStatic
    fun main(args: Array<String>) {
        log.error("Cake", StructuredArguments.keyValue("caketype", "chocolate"))
// Without json-config, prints: 15:56:38.134 [main] ERROR Main -- Cake
// With json-config, prints {"timestamp":"2024-11-25 15:54:30.553","level":"ERROR","message":"Cake","logger":"Main","class":"i.g.o.k.s.internal.Slf4jLogger","method":"error","line":"128","thread":"main","caketype":"chocolate"}


        log.atError {
            message = "Cake"
            payload = buildMap {
                put("caketype", "chocolate")
            }
        }
// Without json-config, prints 15:56:38.138 [main] ERROR Main -caketype="chocolate"- Cake
// With json-config, prints {"timestamp":"2024-11-25 15:54:30.565","level":"ERROR","message":"Cake","logger":"Main","class":"Main","method":"main","line":"14","thread":"main"}

    }
}

logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="json" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
            <providers>
                <pattern>
                    <pattern>
                        {
                        "timestamp": "%date{yyyy-MM-dd HH:mm:ss.SSS, Europe/Oslo}",
                        "level": "%level",
                        "message": "%message",
                        "logger": "%logger{30}",
                        "class": "%class{30}",
                        "method": "%method",
                        "line": "%line",
                        "thread": "%thread{30}"
                        }
                    </pattern>
                </pattern>
                <mdc/>
                <arguments/>
            </providers>
        </encoder>
    </appender>
    <root level="debug">
        <appender-ref ref="json" />
    </root>
</configuration>

build.gradle.kts

plugins {
    kotlin("jvm") version "1.9.25"
}

group = "org.example"
version = "1.0-SNAPSHOT"

repositories {
    mavenCentral()
}

dependencies {
    implementation("io.github.oshai:kotlin-logging:7.0.0")
    implementation("org.slf4j:slf4j-api:2.0.16")
    implementation("ch.qos.logback:logback-classic:1.5.11")
    implementation("net.logstash.logback:logstash-logback-encoder:8.0")
}

[github-actions]

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

[oshai]

The method that is eventually called is addKeyValue: https://www.slf4j.org/api/org/slf4j/spi/DefaultLoggingEventBuilder.html#addKeyValue(java.lang.String,java.lang.Object)

I think the pattern config should include the key name, not sure how it was printed before when it's not in the pattern, maybe it was added implicitly.

[sigmanil]

Unfortunately, the log pattern is configured "company wide" here, and as it works fine with the underlying loggers (as evidenced by it working with the old method 🤔 ), its going to be a bit difficult to convince anyone it needs to be changed. :-(

[oshai]

Please try to check if this is really solve the problem (hence the root cause), before we decide how to tackle it.

[sigmanil]

Attempt 1
So, with the same examples as above, my first attempt was adding:

"caketype": "%caketype"

to the pattern, hoping the latter part of it would reference the key. This resulted in an error message:

Invalid [pattern]: Invalid JSON property '//caketype' (was '%caketype'): Failed to interpret '%caketype' conversion word.

Which is fair enough, thats just not how it works.

Attempt 2
So I had a look here: https://logback.qos.ch/manual/layouts.html, and the %kvp conversion word seems promising. If I use it, for example like this:

"kvps": "%kvp"

my key/values are indeed output, but as just one single json field, not the same behaviour as earlier. With other fields removed for brevity, it looks like this:

{"kvps":"caketype=\"chocolate\""}

...which is not what is needed.

I can't really see any other way of doing it using the pattern?

I'll try to reproduce it using logback directly without the KotlinLogging layer, see if it works as I expect that way.

[sigmanil]

Calling the underlying logger directly (relevant lines below) with the original log format results in the old behavior.

import org.slf4j.LoggerFactory
private var slf4jLogger = LoggerFactory.getLogger(Main::class.java)
slf4jLogger.error("Cake", StructuredArguments.keyValue("caketype", "chocolate"))

Which leads me to conclude this is the expected behaviour, that structured arguments are included even if not mentioned explicitly in the json output.

Observation
I do notice, that when using the old deprecated method from KotlinLogging, it logs i.g.o.k.s.internal.Slf4jLogger as the logging class, which it doesn't for the other cases (see my original examples). This seems similar to #416 - but in that issue it says that slf4j 2.0.13 solved the problem, which it doesn't for me. Not sure it has anything to do with the other problem.

[sigmanil]

Some debugging later, it seems that with the old method, and when using the underlying slf logger, the "payload" is added to the LoggingEvents argumentArray. The atError-etc methods of KotlinLogging are setting the keyValuePairs of the LoggingEvent, which may be intentional, but not what I need.

So what I'm looking for is a non-deprecated way of passing arguments to the LoggingEvents argumentArray through KotlinLogging.

[oshai]

I think the cause is an issue in how slf4j works now with fluent logging and structured arguments.
Do you want to try and ask in that project?

I can try a workaround of adding to the argument array.

[sigmanil]

I think the cause is an issue in how slf4j works now with fluent logging and structured arguments. Do you want to try and ask in that project?

Considering the slf4j framework works the same way as before (and the methods there aren't deprecated), I'm not sure how they could help?

[oshai]

Slf4j introduced a new fluent api which we now use: https://www.slf4j.org/manual.html#fluent

Though the old api there is not deprecated, it seems the new api do not behave like the old one.

[sigmanil]

I can try a workaround of adding to the argument array.

Thank you! 🤩 I get a bit lost when looking at the inner workings of loggers, but my initial instinct is that the arguments could maybe be added as another parameter to the atError-etc methods? Meaning adding another map arguments to KLoggingEventBuilder, which could then be used to call LoggingEventBuilder.addArgument somewhere in the LocationAwareKLogger - possibly in at or logWithPayload?

I'll try to check if using the addArgument in the LoggingEventBuilder (which, if I'm understanding your link correctly is part of the fluent api?) reproduces the desired behaviour.

[oshai]

Ok. I now recall that we also have direct logback usage: #452

Either we can see if it works there, or a fix there might be simpler as it bypasses slf4j.

[sigmanil]

I'll try to check if using the addArgument in the LoggingEventBuilder (which, if I'm understanding your link correctly is part of the fluent api?) reproduces the desired behaviour.

It does.

private var logger = LoggerFactory.getLogger(Main::class.java)
logger.atError().addArgument(StructuredArguments.keyValue("caketype", "chocolate")).setMessage("Cake").log()

outputs

{"timestamp":"2024-11-26 10:09:41.361","level":"ERROR","message":"Cake","logger":"Main","class":"Main","method":"main","line":"14","thread":"main","caketype":"chocolate"}

So my suggestion then is to add a field arguments of type Set to KLoggingEventBuilder that is then used to call the addArgument method.

That would allow us to log like this:

log.atError() {
  message = "message"
  arguments = listOf( ...arguments, in whatever way compatible with the underlying framework...)
  payload = mapOf ( ...key value pairs as before, no change here )
}

[oshai]

ok, I think that makes sense. It might conflict with #452 but I guess no one expects to use both positional arguments and kotlin style message inference. So I guess we can decide to use only one of those lists. Would you like to create a PR for that?

[sigmanil]

I had a look at #452 earlier but I didn't quite understand it, I'm afraid. :-(

I will try making a PR when I get the time, might be a day or two!