GKE & Stackdriver: Java logback logging format?
Asked Answered
J

3

15

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!

June answered 24/5, 2017 at 17:9 Comment(0)
J
16

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.

June answered 24/5, 2017 at 21:1 Comment(4)
i would avoid including [%thread] %-5level in the <pattern/> as its already part of the jsonPayload. And recommend adding method name to the log: %logger{36}.%M Harwilll
It took me some time until I realise that the google-cloud-logging-logback library (cloud.google.com/logging/docs/setup/java) is not meant to be used inside GKE, but in case you have a regular VM. This seems to be the right way to make structured logging with minimal effort for google cloud logging. This should be a library that you can pull in as a dependency :)Trollope
It seems there is a library that is compatible with the structured format which Google Cloud Logging uses - Logstash (logstash-logback-encoder). See this issue for more details: github.com/googleapis/google-cloud-java/issues/…Trollope
We run our container in gke and just log to stdout with the logstash logback appender. Works without issues.Molluscoid
F
2

Google has provided a logback appender for Stackdriver, I have enhanced it abit to include the thread name in the logging label, so that it can be searched more easily.

pom.xml

<dependency>
    <groupId>com.google.cloud</groupId>
    <artifactId>google-cloud-logging-logback</artifactId>
    <version>0.116.0-alpha</version>
</dependency>

logback-spring.xml

<springProfile name="prod-gae">
    <appender name="CLOUD"
        class="com.google.cloud.logging.logback.LoggingAppender">
        <log>clicktrade.log</log>
        <loggingEventEnhancer>com.jimmy.clicktrade.arch.CommonEnhancer</loggingEventEnhancer>
        <flushLevel>WARN</flushLevel>
    </appender>
    <root level="info">
        <appender-ref ref="CLOUD" />
    </root>
</springProfile>

CommonEnhancer.java

public class CommonEnhancer implements LoggingEventEnhancer {

    @Override
    public void enhanceLogEntry(Builder builder, ILoggingEvent e) {
        builder.addLabel("thread", e.getThreadName());
    }

}

Surprisingly, the logback appender in MVN repository doesn't align with the github repo source code. I need to dig into the JAR source code for that. The latest version is 0.116.0-alpha, it seems it has version 0.120 in Github

https://github.com/googleapis/google-cloud-java/tree/master/google-cloud-clients/google-cloud-contrib/google-cloud-logging-logback

Frication answered 1/1, 2020 at 6:50 Comment(1)
As the question is related to java running in Docker and fluentd agent doing the job of logging the STDOUT to Stackdriver - this answer is misleading, as the google-cloud-logging-logback is using REST/gRPC for each log entry.Harwilll
H
1

You can use the glogging library.

Simply add it as a dependency and use provided layout in logback.xml:

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="io.github.aaabramov.glogging.GoogleLayout">

                <!-- You have a choice which JSON encoder to use. Or create your own via implementing JsonEncoder interface -->
                <json>io.github.aaabramov.glogging.JacksonEncoder</json>

                <!-- OR -->
                <!-- <json>io.github.aaabramov.glogging.GsonEncoder</json> -->

                <!-- Optionally append "${prefix}/loggerName" labels -->
                <appendLoggerName>true</appendLoggerName>

                <!-- Optionally configure prefix for labels -->
                <prefix>com.yourcompany</prefix>

                <!-- Provide message pattern you like. -->
                <!-- Note: there is no need anymore to log timestamps & levels to the message. Google will pick them up from specific fields. -->
                <pattern>%message %xException{10}</pattern>
            </layout>
        </encoder>
    </appender>

    <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="STDOUT"/>
    </appender>

    <!--  Configure logging levels  -->
    <logger name="com.github" level="DEBUG"/>

    <root level="DEBUG">
        <appender-ref ref="ASYNCSTDOUT"/>
    </root>
</configuration>

It will produce messages in the format that GSL will gladly accept:

{"timestamp":{"seconds":1629642099,"nanos":659000000},"severity":"DEBUG","message":"debug","labels":{"io.github.aaabramov/name":"Andrii","io.github.aaabramov/loggerName":"io.github.aaabramov.glogging.App"}}

Disclaimer: I am the author of this library.

Credits: https://mcmap.net/q/777299/-gke-amp-stackdriver-java-logback-logging-format

Hayman answered 22/2, 2023 at 12:37 Comment(2)
Nice library, thanks for sharing! With it, can I also use json structure inside the message?Adonis
@Adonis You mean something like {"timestamp":{"seconds":1629642099,"nanos":659000000},"other":"params","message":{"this-is":"json"}} ?Hayman

© 2022 - 2024 — McMap. All rights reserved.