[Feature Request] Structured Logging

[qoomon]

would be nice to have a shortcut for single MDC logging.
I would like to write code like this

log.info { "add Item to basket".fields("accountId" to "123456789", "itemId" to "123456789") } 

instead of

withLoggingContext("accountId" to "123456789", "itemId" to "123456789") {
    log.info { "add Item to basket" }
}

I need that feature to be able to log this key value pairs as json fields.
Inspired by the slf4j structured logging feature https://stackoverflow.com/a/58710096/5376635

[github-actions]

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

[qoomon]

Example implementation

fun KLogger.info(msg: () -> String, fields: (MutableMap<String, String?>) -> Unit) {
    if (isInfoEnabled) {
        val context = mutableMapOf<String, String?>().apply { fields(this) }
        withLoggingContext(context) { info(msg) }
    }
}

Example usage

log.info({ "add item" }) {
    it["accountId"] = "123456789"
    it["basketId"] = "123456789"
}

[oshai]

Thanks for the suggestion!
I don't feel like this adds enough value / save enough overhead to be added to the api of the lib.

[qoomon]

I understand, however maybe a lazy context method like fun withLoggingContext(context: (MutableMap<String, String?>) -> Unit, block: () -> Unit)

[oshai]

is there a difference from the function we already have:

public inline fun <T> withLoggingContext(
    map: Map<String, String?>,
    restorePrevious: Boolean = true,
    body: () -> T
): T {
...

[qoomon]

yes, the map is not lazy so all values needs to be calculated regardless of logging level

[qoomon]

just in case you change your mind, all methods with lazy context as extension functions

Usage

log.info { "moin moin" }

log.info({ "moin moin - with LoggingContext" }) {
    it["accountId"] = "123456789"
    it["basketId"] = "123456789"
}

withLoggingContext({
    it["accountId"] = "123456789"
    it["basketId"] = "123456789"
}) {
    log.info { "moin moin - withLoggingContext()" }
}

Implementation

package me.qoomon.enhancements.kotlinlogging

import mu.KLogger
import mu.withLoggingContext
import org.slf4j.Marker

// --- KLogger Lazy Context Extensions ---------------------------------------------------------------------------------

/**
 * Lazy add a log message if isTraceEnabled is true
 */
fun KLogger.trace(
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { trace(msg) }
    }
}

/**
 * Lazy add a log message if isDebugEnabled is true
 */
fun KLogger.debug(
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isDebugEnabled) {
        withLoggingContext(loggingContext) { debug(msg) }
    }
}

/**
 * Lazy add a log message if isInfoEnabled is true
 */
fun KLogger.info(
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isInfoEnabled) {
        withLoggingContext(loggingContext) { info(msg) }
    }
}

/**
 * Lazy add a log message if isWarnEnabled is true
 */
fun KLogger.warn(
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isWarnEnabled) {
        withLoggingContext(loggingContext) { warn(msg) }
    }
}

/**
 * Lazy add a log message if isErrorEnabled is true
 */
fun KLogger.error(
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isErrorEnabled) {
        withLoggingContext(loggingContext) { error(msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isTraceEnabled is true
 */
fun KLogger.trace(
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { trace(t, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isDebugEnabled is true
 */
fun KLogger.debug(
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isDebugEnabled) {
        withLoggingContext(loggingContext) { debug(t, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isInfoEnabled is true
 */
fun KLogger.info(
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isInfoEnabled) {
        withLoggingContext(loggingContext) { info(t, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isWarnEnabled is true
 */
fun KLogger.warn(
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isWarnEnabled) {
        withLoggingContext(loggingContext) { warn(t, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isErrorEnabled is true
 */
fun KLogger.error(
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isErrorEnabled) {
        withLoggingContext(loggingContext) { error(t, msg) }
    }
}

/**
 * Lazy add a log message if isTraceEnabled is true
 */
fun KLogger.trace(
    marker: Marker?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { trace(marker, msg) }
    }
}

/**
 * Lazy add a log message if isDebugEnabled is true
 */
fun KLogger.debug(
    marker: Marker?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isDebugEnabled) {
        withLoggingContext(loggingContext) { debug(marker, msg) }
    }
}

/**
 * Lazy add a log message if isInfoEnabled is true
 */
fun KLogger.info(
    marker: Marker?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isInfoEnabled) {
        withLoggingContext(loggingContext) { info(marker, msg) }
    }
}

/**
 * Lazy add a log message if isWarnEnabled is true
 */
fun KLogger.warn(
    marker: Marker?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isWarnEnabled) {
        withLoggingContext(loggingContext) { warn(marker, msg) }
    }
}

/**
 * Lazy add a log message if isErrorEnabled is true
 */
fun KLogger.error(
    marker: Marker?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isErrorEnabled) {
        withLoggingContext(loggingContext) { error(marker, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isTraceEnabled is true
 */
fun KLogger.trace(
    marker: Marker?,
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { trace(marker, t, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isDebugEnabled is true
 */
fun KLogger.debug(
    marker: Marker?,
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isDebugEnabled) {
        withLoggingContext(loggingContext) { debug(marker, t, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isInfoEnabled is true
 */
fun KLogger.info(
    marker: Marker?,
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isInfoEnabled) {
        withLoggingContext(loggingContext) { info(marker, t, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isWarnEnabled is true
 */
fun KLogger.warn(
    marker: Marker?,
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isWarnEnabled) {
        withLoggingContext(loggingContext) { warn(marker, t, msg) }
    }
}

/**
 * Lazy add a log message with throwable payload if isErrorEnabled is true
 */
fun KLogger.error(
    marker: Marker?,
    t: Throwable?,
    msg: () -> Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isErrorEnabled) {
        withLoggingContext(loggingContext) { error(marker, t, msg) }
    }
}

/**
 * Add a log message with all the supplied parameters along with method name
 */
fun KLogger.entry(
    vararg argArray: Any?,
    loggingContext: (LoggingContext) -> Unit
) {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { entry(argArray) }
    }
}

/**
 * Add log message indicating exit of a method
 */
fun KLogger.exit(loggingContext: (LoggingContext) -> Unit) {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { exit() }
    }
}

/**
 * Add a log message with the return value of a method
 */
fun <T> KLogger.exit(result: T, loggingContext: (LoggingContext) -> Unit): T where T : Any? {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { exit(result) }
    }
    return result
}

/**
 * Add a log message indicating an exception will be thrown along with the stack trace.
 */
fun <T> KLogger.throwing(throwable: T, loggingContext: (LoggingContext) -> Unit) where T : Throwable {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { throwing(throwable) }
    }
}

/**
 * Add a log message indicating an exception is caught along with the stack trace.
 */
fun <T> KLogger.catching(throwable: T, loggingContext: (LoggingContext) -> Unit) where T : Throwable {
    if (isTraceEnabled) {
        withLoggingContext(loggingContext) { catching(throwable) }
    }
}

typealias LoggingContext = MutableMap<String, String?>

fun <T> withLoggingContext(
    loggingContext: (LoggingContext) -> Unit,
    restorePrevious: Boolean = true,
    body: () -> T
) = withLoggingContext(mutableMapOf<String, String?>().apply { loggingContext(this) }, restorePrevious, body)

[janhaesen]

Aside from implementation I think that structured/contextualized logging is something of great importance for the DEV OPS side of things. Where I think that perhaps the suggested solution could be different is by providing a plugin or way of configuration to use, for instance, Elastic Common Schema.

Using ECS (Elastic Common Schema) provides a way of sending structured logging statements to an Elastic cluster and be able to search if efficiently without large cost that could come with an unstructured logging setup. The main reason being that Elastic is aware of the structure and keys, so that it can index accurately. Besides this clear performance benefit it also provides a means of consistency to know how to look for things. A Java implementation of this is: log4j2-ecs-layout.

That being said, I wanted to provide my 2 cents and I completely understand that this isn't something in the scope of the library, except for perhaps the plugin option. I'd be happy to further discuss this in private if interested and open for this option. I would also would be glad to contribute to such a solution.

[bomgar]

The new slf4j 2.0 API has support for key values Pairs
https://www.slf4j.org/manual.html#fluent

I guess this is something that should be supported here as well.

2022-08-20 - Release of SLF4J 2.0.0

[oshai]

PR #234 will upgrade to slf4j 2.
The fluent api reminds me of flogger.

Is there any reference to mdc in the new api?

I think the way to do that nicer in kotlin is having one method/class with defaults and named params.

[aiguofer]

I was about to create an issue suggesting the ability to do something like:

                logger.debug {
                    withLoggingContext("expensive_value" to someExpensiveCall()) {
                        "Thing happened"
                    }
                }

But the above implementation seems pretty good as well.

The use-case as @qoomon pointed out is to only calculate expensive operations if the desired log level is enabled.

I'm just learning about Java/Kotlin logging so I'm still unfamiliar, but I had implemented a similar thing in python that allowed me to do something like logger.info("Message", extra={"key": expensiveCall}) and expensiveCall would only get called if the logging level was enabled.

[oshai]

Looking at this again there are few things to note about such api:
Usually withLoggingContext will put something in thread local, so users expected that the inner body will not be just log methods, but also other things that should be executed regardless of the log level.
I might even get more obscure when working with coroutines or threads (as we need to pass the mdc context around, but not sure it was set at all).
So maybe a reasonable api will be:

logger.withDebugLoggingContext ({"a" = "b"}) {
  // do something
  logger.debug { "with a to b" }
}

I still not convinced such api looks good enough, and given that it's easy to write such additional extension function as provided above I don't see enough motivation to add it to the lib.

[aiguofer]

There's some good points raised here. In my case we're using the logback logstash encoder, so with the above examples I think we're just going to add some extensions like this:

import mu.KLogger
import net.logstash.logback.marker.Markers.appendEntries

/*
 Extensions to easily add key/value pairs to log messages in idiomatic kotlin using
 lazy evaluations

 Example

 logger.debug({ "Message with lazy $interpolation" }) {
    it["thing"] = "thang"
    it["expensive_thing"] = expensiveCall()
 }

 */

fun KLogger.debug(
    msg: () -> Any?,
    extra: (MutableMap<String, Any?>) -> Unit
) {
    if (isInfoEnabled) {
        val entries = mutableMapOf<String, Any?>().apply { extra(this) }
        info(appendEntries(entries), msg)
    }
}

It seems like it should be easy enough to do the same with v4.

[dhoepelman]

I also support structured logging. A major difference with MDC (like withLoggingContext(Async)) is that it can be any complex object instead of only key with string values. A nice implementation difference is that structured logging sidestep the thread local MDC manipulation.

Here are some extension methods that use logback-logstash-encoder's Marker's to do structured logging like

log.info("foo" to listOf("bar","baz"))) {
  "My message"
}

/** Convenience function to create a [LogstashMarker]. */
fun marker(pair: Pair<String, Any>): LogstashMarker = Markers.append(pair.first, pair.second)

/** Convenience function to create a [LogstashMarker]. */
fun markers(vararg pairs: Pair<String, Any>): LogstashMarker = if (pairs.size == 1) marker(pairs[0]) else Markers.appendEntries(mapOf(*pairs))

// Extension functions to add strucutred logging to kotlin-logging
fun KLogger.trace(vararg pairs: Pair<String, Any>, msg: () -> Any?) = trace(markers(*pairs), msg)
fun KLogger.debug(vararg pairs: Pair<String, Any>, msg: () -> Any?) = debug(markers(*pairs), msg)
fun KLogger.info(vararg pairs: Pair<String, Any>, msg: () -> Any?) = info(markers(*pairs), msg)
fun KLogger.warn(vararg pairs: Pair<String, Any>, msg: () -> Any?) = warn(markers(*pairs), msg)
fun KLogger.error(vararg pairs: Pair<String, Any>, msg: () -> Any?) = error(markers(*pairs), msg)

fun KLogger.trace(t: Throwable, vararg pairs: Pair<String, Any>, msg: () -> Any?) = trace(markers(*pairs), t, msg)
fun KLogger.debug(t: Throwable, vararg pairs: Pair<String, Any>, msg: () -> Any?) = debug(markers(*pairs), t, msg)
fun KLogger.info(t: Throwable, vararg pairs: Pair<String, Any>, msg: () -> Any?) = info(markers(*pairs), t, msg)
fun KLogger.warn(t: Throwable, vararg pairs: Pair<String, Any>, msg: () -> Any?) = warn(markers(*pairs), t, msg)
fun KLogger.error(t: Throwable, vararg pairs: Pair<String, Any>, msg: () -> Any?) = error(markers(*pairs), t, msg)

[imherrera]

I'm currently using the logging event builder of slf4j, i think it would be useful to have something similar here

private inline fun KLogger.doWarn(block: org.slf4j.spi.LoggingEventBuilder.() -> Unit) {
    if (isWarnEnabled) {
        (underlyingLogger as org.slf4j.Logger).atWarn()
            .apply(block)
            .log()
    }
}

then it can be used as

logger.doWarn {
    setMessage("Will backoff due to a sequence of errors!")
    addKeyValue("backoffMillis", backoffMillis)
    addKeyValue("errorSequence", errorSequence)
}

[oshai]

I like the syntax. Maybe one improvement can be to have setters like:

message = "my message"
map["mykey"] = obj

Etc'

[imherrera]

I agree, having this api would be really useful and it has two advantages over using MDC, we can store objects instead of only strings, and the api is explicit thus avoiding confussion especially when coroutines are used.

[imherrera]

I have written a prototype of how it could look like, what do you think?

class KLoggingEventBuilder {
    var message: String? = null
    var marker: io.github.oshai.kotlinlogging.Marker? = null
    var cause: Throwable? = null
    var extra: Map<String, Any>? = null
}

inline fun KLogger.doWarn(block: KLoggingEventBuilder.() -> Unit) {
    if (isWarnEnabled) {
        KLoggingEventBuilder()
            .apply(block)
            .run { warn(marker, message, cause, /* TODO: accept map as parameter for structured logging?*/ extra) }
    }
}

fun example() {
    val logger = KotlinLogging.logger { }
    val info = mapOf("foo" to 1, "bar" to "x")

    logger.doWarn {
        message = "Some log message"
        extra = info
    }

    try {
        // something risky
    } catch (e: Throwable) {
        logger.doWarn {
            message = "Some log message"
            extra = info
            cause = e
        }
    }
}

[oshai]

The interface looks pretty good. Few suggestions:

• extra should be named differently? maybe map or context?
• extra should be mutable map (with empty default map) so we can set keys directly.

[imherrera]

How about 'payload', and as for the field being a null variable i think it is more flexible than having a default empty mutable map, sometimes we may not set any field at all and the map will still be instantiated, if many fields need to be set there is the buildMap method

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

Also if we make it a variable we can share a single map between log statements

val commonPayload = buildMap(capacity = 3) {
    put("foo", 1)
    put("bar", "x")
    put("obj", Pair(2, 3))
}
try {
    // something that may throw
} catch (e: Exception) {
    logger.doWarn {
        message = "failed operation"
        payload = commonPayload
        cause = e
    }
} catch (e: Error) {
    logger.doError {
        message = "failed fatally"
        payload = commonPayload
        cause = e
    }
}

[oshai]

Ok, sounds good. Would you like to create a pull request?

[oshai]

I started taking a look at this, looks like the current class hierarchy makes it a bit cumbersome to implement. I opened #329 and might implement those together at version 5.

[oshai]

For reference, I am linking here slf4j impl: https://github.com/qos-ch/slf4j/blob/f871e7f2e9f3f3959e987967655dfcb15494a3d3/slf4j-api/src/main/java/org/slf4j/spi/LoggingEventBuilder.java

[oshai]

See #329 for implementation.