Is there a Logback Layout that Creates JSON Objects with Message Parameters as Attributes?

Question

I want to send log events to Loggly as JSON objects with parameterized string messages. Our project currently has a lot of code that looks like this:

String someParameter = "1234";
logger.log("This is a log message with a parameter {}", someParameter);

We're currently using Logback as our SLF4J backend, and Logback's JsonLayout to serialize our ILogEvent objects into JSON. Consequentially, by they time our log events are shipped to Loggly, they look like this:

{
    "message": "This is a log message with a parameter 1234",
    "level": INFO,
    ....
}

While this does work, it sends a different message string for every value of someParameter, which renders Loggly's automatic filters next to useless.

Instead, I'd like to have a Layout that creates JSON that looks like this:

{
    "message": "This is a log message with a parameter {}",
    "level": INFO,
    "parameters": [
        "1234"
    ]
}

This format would allow Loggly to group all log events with the message This is a log message with a parameter together, regardless of the value of someParameter.

It looks like Logstash's KV filter does something like this - is there any way to accomplish this task with Logback, short of writing my own layout that performs custom serialization of the ILogEvent object?

Solution 1

You could use a Mapped Diagnostic Context to set a stamp for each of those type of log messages that you could then filter on once in loggly.

According to the source of JsonLayout the stamp is stored as a separate value in the JSON.

Solution 2

There is a JSON logstash encoder for Logback, logstash-logback-encoder

Solution 3

So for me I was trying to log execution times, I created a pojo called ExecutionTime with name, method, class, duration.

I was then able to create it:

ExecutionTime time = new ExecutionTime("Controller Hit", methodName, className, sw.getTotalTimeMillis());

For logging I then used:

private final Logger logger = LoggerFactory.getLogger(this.getClass());
logger.info(append("metric", time), time.toString());

Make sure you have:

import static net.logstash.logback.marker.Markers.append;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

This will log something like this:

{  
   "ts":"2017-02-16T07:41:36.680-08:00",
   "msg":"ExecutionTime [name=Controller Hit, method=setupSession, className=class com.xxx.services.controllers.SessionController, duration=3225]",
   "logger":"com.xxx.services.metrics.ExecutionTimeLogger",
   "level":"INFO",
   "metric":{  
      "name":"Controller Hit",
      "method":"setupSession",
      "className":"class com.xxx.services.controllers.SessionController",
      "duration":3225
   }
}

Might be a different set up as I was using logback-spring.xml to output my logs to json:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/base.xml"/>
    <property name="PROJECT_ID" value="my_service"/>
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>app/logs/${PROJECT_ID}.json.log</File>
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <fieldNames>
                <timestamp>ts</timestamp>
                <message>msg</message>
                <thread>[ignore]</thread>
                <levelValue>[ignore]</levelValue>
                <logger>logger</logger>
                <version>[ignore]</version>
            </fieldNames>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
            <maxIndex>10</maxIndex>
            <FileNamePattern>app/logs/${PROJECT_ID}.json.log.%i</FileNamePattern>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>20MB</MaxFileSize>
        </triggeringPolicy>
    </appender>
    <logger name="com.xxx" additivity="false" level="DEBUG">
        <appender-ref ref="FILE"/>
        <appender-ref ref="CONSOLE"/>
    </logger>
    <root level="WARN">
        <appender-ref ref="FILE"/>
    </root>
</configuration>

Solution 4

Here's a recently created project that provides a JSON-specific logging API and works with SLF4J:

https://github.com/savoirtech/slf4j-json-logger

Solution 5

Like already answered you'll get a one-dimensional JSON tree with MDC and/or using a Marker with logstash-logback-encoder.

If you are also looking for the following:

• codebooks for definition of logged datatype key and type,
• configuration of log-aggregation tools (like elasticsearch)
• generated Java helper-code for efficient and correct logging

then try a project I've created: json-log-domain. It defines a simple YAML-format definition from which the above can be generated.

An example helper-code statement would be

logger.info(host("localhost").port(8080), "Hello world");

while generated markdown would like something like this.

View more solutions

Comments

[Leonard Brünings]

The problem I see with your example is that you do not know where the parameter would be inserted in the message.

[MusikPolice]

@LeonardBrünings that shouldn't matter, because the parameters are passed to the log.log(message, param1, param2); function. As long as order is preserved in the array that's inserted into the JSON object, all is good.

[Leonard Brünings]

but your message in the json did not have any placeholders. If that intentional and not a mistake you would not know how to render the correct message.

[MusikPolice]

@LeonardBrünings added the placeholder to the sample output JSON

[MusikPolice]

Yup, this is what we ended up using to add arbitrary objects to our log messages.

[MusikPolice]

That's a nice little library. I doubt I'll switch existing projects over to it, as it would require a fair bit of work, but I'll definitely keep it in mind for future projects.

[ash]

Thank you @MusikPolice - we appreciate the feedback.

[mvmn]

I'm starting a new project now and will try this out. However, I'm not sure if I can configure default fields to include in log (I managed to do that with Logback, but I don't like relying on MDC to output any field, so I would prefer slf4j-json-logger with it's API). The idea is to have a field+value configured in config file, which would end up automatically added to all produced JSON log lines/objects. Is that possible in slf4j-json-logger?

[ash]

There is no feature for that now. Should be relatively easy to accomplish. Please either post this as an issue on github (here github.com/savoirtech/slf4j-json-logger/issues), or contribute a PR!

[Mark Schäfer]

The approach is nice and we tried it, but since the log messages of libraries are NOT formatted as JSON it was of no use for us.

[Eric Huang]

Can you provide example?

[Amit Kumar]

The developer will have to add and remove the values from MDC, which does not make it elegant

[techsavvy]

On applying the similar pattern - I see the "metrics" data log duplicated. It came as part of message and separate node as "metric" - same information printed ? Any suggestions please ?

[techsavvy]

I could resolve that duplicate issue as follows. logger.info("TROS Process Update ",append("trosdata",cleanerLogData),cleanerLogData); now message got value " TROS Proces Update"

[andrewps]

Yeah the second param is the msg ie: logger.info(append("metric", metricObject), msgString); So you just need to change msgString to something else.