Logs generated using SLF4J's addKeyValue method do not log correctly.

[rgoers]

Description

See https://jira.qos.ch/browse/SLF4J-600. It seems SLF4J added an addKeyValue method to its fluent API. When this is called the data is not being added to a MapMessage as it needs to be.

Configuration

Version: 2.20.0

Logs

When SLF4J routes to Log4j the output looks like:

[19.09.2023 19:25:51,248] [INFO ] - slf4j2-with-log4j - Measure times:

None of the key/value pairs are present.

Reproduction

The code has

    private static final Logger LOG = LoggerFactory.getLogger("PERFORMANCE");
    ...

        LOG.atInfo().setMessage("slf4j2-with-log4j - Measure times:")
            .addKeyValue("myDocId", documentId)
            .addKeyValue("myInitExtractorInMs", createFormExtractor)
            .addKeyValue("myvalidatedDocumentInMs", validatedDocument)
            .addKeyValue("myreadPageInMs", readPage)
            .addKeyValue("mytransformInfosInMs", transformInfos)
            .log();

To work properly this needs to translate into

    StringMapMessage log4jMap = new StringMapMessage()
            .with("message", "direct log4j implementation - Measure times:")
            .with("myDocId", documentId)
            .with("myInitExtractorInMs", createFormExtractor)
            .with("myvalidatedDocumentInMs", validatedDocument)
            .with("myreadPageInMs", readPage)
            .with("mytransformInfosInMs", transformInfos);
        LogManager.getLogger("PERFORMANCE").info(log4jMap);

Note that IMO it would be better for Log4j's LogBuilder add support for addKeyValue and internally populate a MapMessage.

[ppkarwasz]

The way I implemented it addKeyValue always adds values to the context map.

We might improve this behavior:

• if the user provides a message as in the example above, we keep the current behavior: the event will contain a SimpleMessage/ParameterizedMessage and the key/value pairs will end up in the context map,
• if the user provides no message we can create a StringMapMessage with all the values.

[rgoers]

Looking at the SLF4J 2 bridge I see that key/value pairs are being handled but they are being added to the LogEvent's ThreadContextMap. I really don't think this is the correct behavior. If key/value pairs are specified we should be creating a MapMessage and logging that. Even if they provide a message that should just be a key/value pair in the MapMessage with a key of "message". That is typically how I have implemented all my logging that uses MapMessages. You can also see that the original reporter does the same. I don't think key/value pairs provided in the logging call belong in the ThreadContextMap at all. That also seems to align with how SLF4J/Logback has implemeneted it, although I believe he is serializing the Map into a String in the call to log() (i.e. before it actually makes it into the guts of Logback).

Also, I don't know why we wouldn't just add a withMap() method to add the whole Map in one operation if that is easier for the user, in addition to adding withKeyValue() methods.

[ppkarwasz]

What if the user wants to format the message as text? Using:

logger.atInfo()
      .setMessage("Hello")
      .addKeyValue("key", "value")
      .log();

the expected output in Logback (with pattern "%kvp %m") is:

key="value" Hello

Currently a PatternLayout with pattern %X %m outputs:

{key=value} Hello

After your proposed changes it would output:

{key=value, message=Hello}

We probably need a new message type or we need to nest a MapMessage as parameter of a ParameterizedMessage.

Edit: @rgoers, reading your comment again and looking at the way MapMessage is used in practice, e.g. in the Open Telemetry LogEventMapper class, I convinced myself that your approach is the correct one. The "standard" way to extract a traditional message from a MapMessage seems to be calling mapMessage.getFormat() or mapMessage.get("message").

[rgoers]

If a user wanted

{key-value) Hello

then they should use %map with new options to specify if the map should be formatted as JSON and to extract the message attribute and print it separately. Something like

%map{}{JSON}{%m}

I would also enhance %map so that %map(message) would just print the value of the message key. I can also see enhancing MapMessage to add the message as a separate attribute instead of relying on the name of the key. In that case the third option would be unneccesary as the value of the message attribute would always be logged separately at the end if it is non-null.

A new message type is not necessary.

[ppkarwasz]

I can also see enhancing MapMessage to add the message as a separate attribute instead of relying on the name of the key. In that case the third option would be unneccesary as the value of the message attribute would always be logged separately at the end if it is non-null.

I think this would be the best options. As far as I can understand the new SLF4J features allow to create messages similar to RFC5424 (minus the SD-ID) with a message and a map of key-values, so it should be similar to the StructuredDataMessage. Although I am not sure what we should do if the user provides a message format, some parameters and a set of key/value pairs.

[yvasyliev]

Looking forward to the implementation of this feature. 😊

[ppkarwasz]

@rgoers,

What about the solution proposed in this SO question?