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!
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.
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
