CODEWITHSUNDEEP
javajsonloggingslf4jlogback
kei1aeh5quahQu4U
kei1aeh5quahQu4U

Reputation: 153

Java: How to log raw JSON as JSON and avoid escaping during logging with logback / slf4j

I'm using SLF4J with Logback in a JAX-RS application... I want to log to JSON in such a way that my message is not encoded again but printed raw into the logfile:

At the moment it looks like this:

{"@timestamp":1363834123012,"@message":"{\"text\":\"From MLK to Barack 
Ob...\n\"}"

But I want to have this: 

  {"@timestamp":1363834123012,"@message": { "text ": "From MLK to Barack 
Ob...\n\}

The reason is I want to parse the JSON again and want to avoid the unescaping of the data.

I've written a custom logback encoder but I found no way to avoid the escaping. Can I pass a object to logback and change the settings based on the type of the object?

Edit: I've found a way - not exactly elegant - as requested a SSCE:

In my Application

// SLF4J Logger
private static Logger logger = LoggerFactory.getLogger(MyClass.class);
// A logback? Marker
private Marker foo = MarkerFactory.getMarker("foo");
// Jackson ObjectMapper()
ObjectMapper mapper = new ObjectMapper();

// Log something... 
logger.info(foo, mapper.writeValueAsString(json));

I've used a variation of the Logstash-Encoder found here: https://github.com/logstash/logstash-logback-encoder

package my.package;

import static org.apache.commons.io.IOUtils.*;

import java.io.IOException;
import java.util.Map;
import java.util.Map.Entry;

import org.codehaus.jackson.JsonGenerator.Feature;
import org.codehaus.jackson.JsonNode;
import org.codehaus.jackson.map.ObjectMapper;
import org.codehaus.jackson.node.ObjectNode;
import org.slf4j.Marker;

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.classic.spi.IThrowableProxy;
import ch.qos.logback.classic.spi.ThrowableProxyUtil;
import ch.qos.logback.core.CoreConstants;
import ch.qos.logback.core.encoder.EncoderBase;

public class JsonEncoder extends EncoderBase<ILoggingEvent> {

    private static final ObjectMapper MAPPER = new ObjectMapper().configure(
        Feature.ESCAPE_NON_ASCII, true);
    private static Marker M;

    private boolean immediateFlush = true;

@Override
public void doEncode(ILoggingEvent event) throws IOException {

    M = event.getMarker();

    ObjectNode eventNode = MAPPER.createObjectNode();

    eventNode.put("@timestamp", event.getTimeStamp());
    //
    if (M != null) {
        if (M.getName().equals("foo")) {
            JsonNode j = MAPPER.readTree(event.getFormattedMessage());
            eventNode.put("@foo", j);
        }
    } else {
        eventNode.put("@message", event.getFormattedMessage());
    }
    eventNode.put("@fields", createFields(event));

    write(MAPPER.writeValueAsBytes(eventNode), outputStream);
    write(CoreConstants.LINE_SEPARATOR, outputStream);

    if (immediateFlush) {
        outputStream.flush();
    }

}

private ObjectNode createFields(ILoggingEvent event) {
         // not important here
    return fieldsNode;

}

@Override
public void close() throws IOException {
    write(LINE_SEPARATOR, outputStream);
}

public boolean isImmediateFlush() {
    return immediateFlush;
}

public void setImmediateFlush(boolean immediateFlush) {
    this.immediateFlush = immediateFlush;
}
}

It's works now! Yeah! But I guess it's not the best way to do it (serialize, deserialize the JSON...)

Upvotes: 19

Views: 27581

Answers (7)

Bernhard Kern
Bernhard Kern

Reputation: 278

If you have a Json formatted messages, the upper solutions work, but are not so nice, since you don´t want to call a logstash specific code, each time you use your logger in the code.

Just adding a

net.logstash.logback.encoder.LogstashEncoder

is not enough, since the message itsself stays escaped. To solve this, try the following in your logback.xml:

<encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
  <providers>
    <timestamp/>
    <version/>
    <loggerName/>
    <pattern>
      <pattern>
        {
          "jsonMessage": "#asJson{%message}"
        }
      </pattern>
    </pattern>
  </providers>
</encoder>

The #asJson pattern will unescape your message.

UPDATE:

There is now a tryJson parsing option, that converts the message to json, and if the parsing fails, keep the string as is. (see documentation)

<encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
  <providers>
    <timestamp />
      <pattern>
        <pattern>
          {
            "message": "#tryJson{%message}"
          }
        </pattern>
      </pattern>
    <loggerName/>
  </providers>
</encoder>

This will replace the default message attribute by the logged string, optionally converted to json if possible.

Upvotes: 13

bsautner
bsautner

Reputation: 4822

here is an updated (2016) groovy logback config that dumps out your logs in json format to a file, and debug lines in the console. Took me all day to figure out so i thought i'd update the thread.

    import ch.qos.logback.classic.encoder.PatternLayoutEncoder
import ch.qos.logback.core.ConsoleAppender
import ch.qos.logback.core.rolling.FixedWindowRollingPolicy
import ch.qos.logback.core.rolling.RollingFileAppender
import ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy
import net.logstash.logback.encoder.LogstashEncoder

import static ch.qos.logback.classic.Level.INFO
import static ch.qos.logback.classic.Level.WARN

def PROJECT_ID = "com.foo"

    appender("file", RollingFileAppender) {
        file = "/tmp/logs/${PROJECT_ID}.json"
        encoder(LogstashEncoder)
        rollingPolicy(FixedWindowRollingPolicy) {
            maxIndex = 1
            fileNamePattern = "logs/${PROJECT_ID}.json.%i"
        }
        triggeringPolicy(SizeBasedTriggeringPolicy) {
            maxFileSize = "1MB"
        }
    }


    appender("STDOUT", ConsoleAppender) {
        encoder(PatternLayoutEncoder) {
            pattern = "%d{HH:mm:ss.SSS} %-5level %logger{36} - %msg%n"
        }
    }

    logger("com.foo", INFO, ["STDOUT", "file"], false)

    root(WARN, ["STDOUT", "file"])

Upvotes: 2

John
John

Reputation: 31

Just came over this myself and found an article with a few recommandations on logging.

If you use maven put this dependency into pom.xml

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>3.4</version>
</dependency>

And put something like this into logback.xml

<configuration>
    <property name="PROJECT_ID" value="example"/>
    <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>logs/${PROJECT_ID}.json</File>
        <encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
        <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
            <maxIndex>1</maxIndex>
            <FileNamePattern>logs/${PROJECT_ID}.json.%i</FileNamePattern>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>1MB</MaxFileSize>
        </triggeringPolicy>
    </appender>
    <logger name="eu.kielczewski" additivity="false" level="INFO">
        <appender-ref ref="file"/>
    </logger>
    <root level="WARN">
        <appender-ref ref="file"/>
    </root>
</configuration>

This creates example.json file under logs/. The file is rolled once when it reaches 1MB in size.

LOGGER.debug(append("object", someObject), "log message");

Upvotes: 2

HaVonTe
HaVonTe

Reputation: 145

I ran into the same problem. I solved it with

<encoder
 class="net.logstash.logback.encoder.LogstashEncoder">          
</encoder

instead of

<encoder
 class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">

In my java code I used: 

SRV_PERF_LOGGER.info(net.logstash.logback.marker.Markers.appendRaw("message", jackson.writeValueAsString(dto)), null);

Upvotes: 3

AxelW
AxelW

Reputation: 319

Use the RawJsonAppendingMarker:

log.trace(net.logstash.logback.marker.Markers.appendRaw("jsonMessage", jsonString), null);

Upvotes: 4

Tadhg
Tadhg

Reputation: 590

I can't see the original code that's causing your problem, but I suspect it might look like this

JsonNode logOutput;
String messageJSONAsString;

...

logOutput.put("@message", messageJSONAsString);
logger.info(objectMapper.writeValueAsString(logOutput);

This will produce escaped JSON in your output because when you put the message into the output JsonNode, Jackson will re-escape it for you to make sure the output is valid JSON.

The solution here is to put the message in your output as an ObjectNode rather than as a string. Usually you already have access to the object as an Object, in which case you can do

ObjectNode jsonObject = objectMapper.valueToTree(messageObject);
logOutput.put("@message", jsonObject)

Otherwise, if your message is a JSON string, then parse it and add it to the output

logoutput.put("@message", objectMapper.readTree(messageJSONAsString));

Upvotes: 0

Ryan Stewart
Ryan Stewart

Reputation: 128899

Logback doesn't do anything unusual with JSON. It's just a string that gets logged as normal. The escaping is probably happening on your end, unless you're talking about some kind of JSON Appender that's writing it out in that format. I'm pretty sure Logback itself doesn't have anything like that, so you'd want to look at wherever you got the Appender from instead if that's your problem. An SSCCE would help with further troubleshooting.

Upvotes: 1

Related Questions