Logging JSON strings as JSON (raw) with SLF4J

[jeromevdl]

I recently asked a question on stack over flow.

I'm the author of Powertools for AWS Lambda Java. We're providing different libraries to help developers adopt best practices on AWS Lambda.
Between others, we're providing a logging module to log information in JSON format with additional context (function name, arn, ...). At the moment, it is log4j only but we're working on a v2 where it will be slf4j and either log4j or logback.

My problem is that JSON messages (for example doing LOG.info(mapper.writeValueAsString(object))) are logged as simple String and thus all the quotes are escaped and it appears dirty in CloudWatch Logs, very hard to read.

Looking at the MessageResolver, to get proper formatting, we should use ObjectMessage, but who really use this? I didn't even know it exists before diving deeper in this resolver.

In the end, I wrote my own resolver, I'm checking if the message is a JSON (using Jackson readTree), and if that's the case, I use the JsonWriter.writeRawString() to avoid the escaped quotes.

If there is a better way, let me know...

[vy]

To the best of my knowledge, SLF4J has one message type composed of a formatting pattern and an array of arguments; whereas Log4j API has an extendable abstract message type with several default implementations: SimpleMessage, ParametrizedMessage (analogous to SLF4J's message type), ObjectMessage, MapMessage, etc. Log4j message types is expected to implement StringBuilderFormattable and/or MultiformatMessage; otherwise, message relies on the layouts' mechanics to handle rendering.

Put another way, Log4j API supports arbitrary message representations, whereas SLF4J supports only parameterized strings. Hence, if SLF4J is your lowest common denominator, you cannot log arbitrarily structured JSON.

That said... You can leverage MDC/NDC supported by both APIs to have some influence on the final JSON structure generated. AFAIU, you want to log a JSON document composed of following fields:

• timestamp
• level
• coldStart
• service
• samplingRate
• message
• functionName
• functionVersion
• functionMemorySize
• functionArn
• xray_trace_id
• function_request_id

You can add these as MDC fields in SLF4J:

import org.slf4j.MDC;

MDC.put("aws:coldStart", "...");
MDC.put("aws:service", "...");

which is analogous to the following in Log4j API:

import org.apache.logging.log4j.ThreadContext;

ThreadContext.put("aws:coldStart", "...");
ThreadContext.put("aws:service", "...");

Later, you can refer to these MDC keys in your JSON Template Layout LogEvent template using the mdc resolver. See Map Resolver Template docs for details. Consider the following example:

{
  "@timestamp": {
    "$resolver": "timestamp",
    "pattern": {
      "format": "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'",
      "timeZone": "UTC"
    }
  },
  "message": {
    "$resolver": "message",
    "stringified": true
  },
  "coldStart": {
    "$resolver": "mdc",
    "key": "aws:coldStart"
  },
  "service": {
    "$resolver": "mdc",
    "key": "aws:service"
  }
}

Looking at the MessageResolver, to get proper formatting, we should use ObjectMessage, but who really use this?

If you use Log4j API, you can use it in various ways. For instance,

logger.info(new StringMapMessage()
        .with("key1", "val1")
        .with("key2", "val2")
        .with("key3", Collections.singletonMap("foo", "bar")));

In the end, I wrote my own resolver, I'm checking if the message is a JSON (using Jackson readTree), and if that's the case, I use the JsonWriter.writeRawString() to avoid the escaped quotes.

That sounds like "a bug waiting to be exploited in disguise of a feature" to me. I suggest you to simply leverage MDC fields instead. If that doesn't work for you, please let us know why; we might assist you further.

[jeromevdl]

Thanks for your complete answer.

We already manage to log a json structure with different information, using the MDC. My question was more about the message itself, which in the end is just one field of this JSON structure.

As of now when we do logger.info("Hello World"); we have the following logged:

{
    "level": "INFO",
    "message": "Hello World",  ⬅️ 
    "cold_start": true,
    "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:my-function",
    "function_memory_size": 512,
    "function_name": "my-function",
    "function_request_id": "93cace4a-f913-4d37-9a53-a6e6b21c49d6",
    "function_version": "$LATEST",
    "service": "helloworld",
    "xray_trace_id": "1-6564a2e9-3a68920768b0b2f2661d87f1",
    "timestamp": "2023-11-27T14:08:47.527Z"
}

And we already permit users to add stuff in the MDC (context).

The problem is when you do this logger.info("{\"products\":[{\"id\":123,\"name\":\"Nintendo DS\",\"price\":249.99},{\"id\":456,\"name\":\"Playstation 5\",\"price\":499.99}]}"); or logger.info(mapper.writeValueAsString(products)), it generates this:

{
    "level": "INFO",
    "message": "{\"products\":[{\"id\":123,\"name\":\"Nintendo DS\",\"price\":249.99},{\"id\":456,\"name\":\"Playstation 5\",\"price\":499.99}]}",
    "cold_start": true,
    "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:my-function",
    "function_memory_size": 512,
    "function_name": "my-function",
    "function_request_id": "93cace4a-f913-4d37-9a53-a6e6b21c49d6",
    "function_version": "$LATEST",
    "service": "helloworld",
    "xray_trace_id": "1-6564a2e9-3a68920768b0b2f2661d87f1",
    "timestamp": "2023-11-27T14:08:47.527Z"
}

Here it's not so hard, the json is small, but when we log the incoming function event or something bigger, it's impossible to read and troubleshoot...

What we wanted is (having the message included as a json structure in the global log event):

{
    "level": "INFO",
    "message": {
        "products": [
            {
                "id": 123,
                "name": "Nintendo DS",
                "price": 249.99
            },
            {
                "id": 456,
                "name": "Playstation 5",
                "price": 499.99
            }
        ]
    },
    "cold_start": true,
    "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:my-function",
    "function_memory_size": 512,
    "function_name": "my-function",
    "function_request_id": "93cace4a-f913-4d37-9a53-a6e6b21c49d6",
    "function_version": "$LATEST",
    "service": "helloworld",
    "xray_trace_id": "1-6564a2e9-3a68920768b0b2f2661d87f1",
    "timestamp": "2023-11-27T14:08:47.527Z"
}

I managed to do this in our custom PowertoolsResolver.

[vy]

I understand your goal, but I am not comfortable with the solution. I mean, I get that you want to enable users to log arbitrary JSON objects in the message field. SLF4J simply doesn't allow that and you workaround this by doing "if it looks like JSON, treat it like JSON". But this creates an ambiguity in your API. Consider the following: What would a user expect logger.info("[1]") to render in the eventual JSON? A "message": "[1]" or a "message": [1]. You simply cannot know and you are making an assumption. A user can very well submit a bug report stating "I don't want this." Not to mention introducing this as a feature is a backward incompatible change.

Allow me to suggest an alternative route:

1. Encourage users that want to log JSON messages to use Log4j API instead
2. Tell SLF4J users about the aws.logging.autoJsonMessageEmbed system property and MDC key
3. In PowertoolsResolver, activate the auto-JSON-message-embed iff either the MDC entry keyed with aws.logging.autoJsonMessageEmbed or the aws.logging.autoJsonMessageEmbed system property is set to true

MDC will enable one-time activation, whereas the Maven property will enable it for all. No ambiguity, clear intent, delivers the goal of enabling SLF4J users to log arbitrary JSON messages.

[jeromevdl]

Thanks, I went into that direction, using a custom key in the MDC to enable or not the JSON logging. Also added a parameter in the LayoutTemplate.json if users want to enable it for all messages.

[ppkarwasz]

@jeromevdl,

As I remarked in the SO question, SLF4J is not an API that allows to log structured data. If I remember my history lesson, the lack of structured logging (specifically an equivalent of StructuredDataMessage) is the reason @rgoers started the Log4j 2.x project in the first place.

A common misconception is that SLF4J is the only logging API that allows you to use a variety of logging backends. That is a simple anachronism that repeats information that was true in 2010. The Log4j API has many implementations (we maintain three: log4j-to-jul, log4j-to-slf4j beyond the reference implementation log4j-core).

Maybe you should consider basing v2 of your tools on the Log4j API? Beyond the flexibility offered by the Message abstraction, one of the main differences between Log4j API and SLF4J is that the former is community driven, whereas the latter uses the BDFL development model.

With the Log4j API you could:

1. Create a custom MessageFactory2 factory that overrides only newMessage(Object) and delegates the rest to the default message factory. [Admittedly we don't have a standard way to retrieve the default factory, but you can look a AbstractLogger#createDefaultMessageFactory],
2. The newMessage(Object) method can return a MultiformatMessage (or even better a MultiFormatStringBuilderFormattable message) that supports at least the "JSON" format.

Users could simply use your message factory like this:

private static final Logger LOG = LogManager.getLogger(MyClass.class, new JacksonMessageFactory(mapper));

public void doSomeLogging() {
    final Object object = ...;
    LOG.trace(object);
}

The advantage of this approach is that serialization is lazy: if the TRACE level is disabled, the Jackson mapper will no be invoked.

[jeromevdl]

A common misconception is that SLF4J is the only logging API that allows you to use a variety of logging backends.

I agree, but unfortunately, this is how it is. People believe this and still use SLF4J for this reason and we must provide a library that matches where the market is. We'll keep it in that way: the abstract logging with SLF4J and 2 implementations (log4j2 and logback), so people can choose. We take in charge the heavy lifting of message formatting (String/JSON) in the library, using the MDC as @vy suggested, plus our custom Resolver (that we already have for Powertools anyway).

[ppkarwasz]

As far as I am concerned an SLF4J call like this:

logger.info("{}", object);

is equivalent to a Logger#info(Object) call in the Log4j API. We can adapt log4j-slf4j-impl and log4j-slf4j2-impl to recognize this logging pattern and log new ObjectMessage(object) (or just object if it is an instance of Message).

[rgoers]

FWIW, you could probably create a JsonObjectMessage that accepts an object and renders it as JSON when getFormattedMessage is called. MapMessage will also format to JSON but your example shows nested objects, not a simple Map.