GKE & Stackdriver: Java logging format?

Question

I have a project that runs Java as a docker on Kubernetes. Logs are automatically picked up by the fluentd agent and end at Stackdriver.

However, the format of the logs is incorrect: multiline logs fall into separate lines of the log in Stackdriver, and all logs have the log level "INFO", even if they are really warning or erroneous.

I was looking for information on how to configure logback to get the correct format for it to work, but I cannot find such a guide in the Google Stackdriver or GKE documentation.

I suppose I should output some form of JSON, but where can I find format information or even guidance on setting up this pipeline correctly.

Thank!

Answer 1

This answer contained most of the information I needed: fooobar.com/questions/838677 / ...

I adapted the answer to fit my exact question, and fix some strange imports and code that seems to be out of date.

logback.xml:

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="my.package.logging.GCPCloudLoggingJSONLayout">
                <pattern>%-4relative [%thread] %-5level %logger{35} - %msg</pattern>
            </layout>
        </encoder>
    </appender>
    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

GCPCloudLoggingJSONLayout:

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.PatternLayout;
import ch.qos.logback.classic.spi.ILoggingEvent;
import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.ObjectMapper;

import java.util.Map;

import static ch.qos.logback.classic.Level.DEBUG_INT;
import static ch.qos.logback.classic.Level.ERROR_INT;
import static ch.qos.logback.classic.Level.INFO_INT;
import static ch.qos.logback.classic.Level.TRACE_INT;
import static ch.qos.logback.classic.Level.WARN_INT;

/**
 * GKE fluentd ingestion detective work:
 * https://cloud.google.com/error-reporting/docs/formatting-error-messages#json_representation
 * http://google-cloud-python.readthedocs.io/en/latest/logging-handlers-container-engine.html
 * http://google-cloud-python.readthedocs.io/en/latest/_modules/google/cloud/logging/handlers/container_engine.html#ContainerEngineHandler.format
 * https://github.com/GoogleCloudPlatform/google-cloud-python/blob/master/logging/google/cloud/logging/handlers/_helpers.py
 * https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry
 */
public class GCPCloudLoggingJSONLayout extends PatternLayout {

    private static final ObjectMapper objectMapper = new ObjectMapper();

    @Override
    public String doLayout(ILoggingEvent event) {
        String formattedMessage = super.doLayout(event);
        return doLayoutInternal(formattedMessage, event);
    }

    /**
     * For testing without having to deal wth the complexity of super.doLayout()
     * Uses formattedMessage instead of event.getMessage()
     */
    private String doLayoutInternal(String formattedMessage, ILoggingEvent event) {
        GCPCloudLoggingEvent gcpLogEvent =
            new GCPCloudLoggingEvent(formattedMessage, convertTimestampToGCPLogTimestamp(event.getTimeStamp()),
                mapLevelToGCPLevel(event.getLevel()), event.getThreadName());

        try {
            // Add a newline so that each JSON log entry is on its own line.
            // Note that it is also important that the JSON log entry does not span multiple lines.
            return objectMapper.writeValueAsString(gcpLogEvent) + "\n";
        } catch (JsonProcessingException e) {
            return "";
        }
    }

    private static GCPCloudLoggingEvent.GCPCloudLoggingTimestamp convertTimestampToGCPLogTimestamp(
        long millisSinceEpoch) {
        int nanos =
            ((int) (millisSinceEpoch % 1000)) * 1_000_000; // strip out just the milliseconds and convert to nanoseconds
        long seconds = millisSinceEpoch / 1000L; // remove the milliseconds
        return new GCPCloudLoggingEvent.GCPCloudLoggingTimestamp(seconds, nanos);
    }

    private static String mapLevelToGCPLevel(Level level) {
        switch (level.toInt()) {
            case TRACE_INT:
                return "TRACE";
            case DEBUG_INT:
                return "DEBUG";
            case INFO_INT:
                return "INFO";
            case WARN_INT:
                return "WARN";
            case ERROR_INT:
                return "ERROR";
            default:
                return null; /* This should map to no level in GCP Cloud Logging */
        }
    }

    /* Must be public for Jackson JSON conversion */
    public static class GCPCloudLoggingEvent {
        private String message;
        private GCPCloudLoggingTimestamp timestamp;
        private String thread;
        private String severity;

        public GCPCloudLoggingEvent(String message, GCPCloudLoggingTimestamp timestamp, String severity,
            String thread) {
            super();
            this.message = message;
            this.timestamp = timestamp;
            this.thread = thread;
            this.severity = severity;
        }

        public String getMessage() {
            return message;
        }

        public void setMessage(String message) {
            this.message = message;
        }

        public GCPCloudLoggingTimestamp getTimestamp() {
            return timestamp;
        }

        public void setTimestamp(GCPCloudLoggingTimestamp timestamp) {
            this.timestamp = timestamp;
        }

        public String getThread() {
            return thread;
        }

        public void setThread(String thread) {
            this.thread = thread;
        }

        public String getSeverity() {
            return severity;
        }

        public void setSeverity(String severity) {
            this.severity = severity;
        }

        /* Must be public for JSON marshalling logic */
        public static class GCPCloudLoggingTimestamp {
            private long seconds;
            private int nanos;

            public GCPCloudLoggingTimestamp(long seconds, int nanos) {
                super();
                this.seconds = seconds;
                this.nanos = nanos;
            }

            public long getSeconds() {
                return seconds;
            }

            public void setSeconds(long seconds) {
                this.seconds = seconds;
            }

            public int getNanos() {
                return nanos;
            }

            public void setNanos(int nanos) {
                this.nanos = nanos;
            }

        }
    }

    @Override
    public Map<String, String> getDefaultConverterMap() {
        return PatternLayout.defaultConverterMap;
    }
}

As I said earlier, the code was originally from a different answer, I just cleaned up the code a bit to better fit my use case.