javagoogle-cloud-platformkuberneteslogbackstackdriver

GKE & Stackdriver: Java logback logging format?


I have a project running Java in a docker image on Kubernetes. Logs are automatically ingested by the fluentd agent and end up in Stackdriver.

However, the format of the logs is wrong: Multiline logs get put into separate log lines in Stackdriver, and all logs have "INFO" log level, even though they are really warning, or error.

I have been searching for information on how to configure logback to output the correct format for this to work properly, but I can find no such guide in the google Stackdriver or GKE documentation.

My guess is that I should be outputting JSON of some form, but where do I find information on the format, or even a guide on how to properly set up this pipeline.

Thanks!


Solution

  • This answer contained most of the information I needed: https://stackoverflow.com/a/39779646

    I have adapted the answer to fit my exact question, and to fix some weird imports and code that seems to have been deprecated.

    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 another answer, I have just cleaned up the code slightly to fit my use-case better.