Logging to App Engine request_log through Logback

Question

I've got an app built on the Ninja Framework using App Engine Standard Environment - Java 11, using the injected Logger that comes with Ninja, which is Apache Logback. Normally, this logs to the stdout of the instance, so all my messages come in one-line-per-entry format, and on the stdout log channel, which is less than convenient when trying to trace a bug in production.

There is a guide up on Google's documentation for logging to Stackdriver with Logback [1], and I've tried this, to no effect: logs now end up in application.log, which is still a separate channel, and the request_log channel is empty.
I've tried changing up the recommended configuration by putting projects/dive-site-overwatch/logs/appengine.googleapis.com%2Frequest_log as the <log> element in logback.xml, which caused all requests to fail because of an "invalid format" on the URL-encoded solidus. Conversely, adding the solidus as-is causes an exception by being an illegal character.

My current Logback config that I have deployed is the following (you can tell I'm running out of ideas...):

<configuration>
    <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

    <appender name = "STDOUT" class = "ch.qos.logback.core.ConsoleAppender">
        <!-- encoders are assigned the type
             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="tech.provingground.dive_overwatch.etc.logging.layouts.StackdriverLayout">
                <pattern>%-4relative [%thread] %-5level %logger{35} - %msg</pattern>
            </layout>
        </encoder>
    </appender>

    <appender name = "CLOUD" class = "com.google.cloud.logging.logback.LoggingAppender">
        <log>application.log</log> <!-- Optional : default java.log -->
        <flushLevel>WARN</flushLevel> <!-- Optional : default ERROR -->
        <enhancer>tech.provingground.dive_overwatch.etc.logging.enhancers.TestEnhancer</enhancer>
        <encoder>
            <layout class="tech.provingground.dive_overwatch.etc.logging.layouts.StackdriverLayout">
                <pattern>%-4relative [%thread] %-5level %logger{35} - %msg</pattern>
            </layout>
        </encoder>
    </appender>

    <root level = "info">
        <appender-ref ref = "CLOUD" />
<!--        <appender-ref ref = "STDOUT" />-->
    </root>
</configuration>

Looking at the standard out of the application, I can see a number of loglines that point to rejected requests from Stackdriver:

java.lang.RuntimeException: java.util.concurrent.TimeoutException: Waited 6 seconds for com.google.common.util.concurrent.CollectionFuture$ListFuture@77fbc3ba[status=PENDING, info=[futures=[[com.google.api.core.ApiFutureToListenableFuture@772ddfb8, com.google.api.core.ApiFutureToListenableFuture@7d905614, com.google.api.core.ApiFutureToListenableFuture@7396512d, com.google.api.core.ApiFutureToListenableFuture@5ad9baf6]]]]
    at com.google.cloud.logging.LoggingImpl.flush(LoggingImpl.java:581)
    at com.google.cloud.logging.LoggingImpl.write(LoggingImpl.java:562)
    at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:215)
    at com.google.cloud.logging.logback.LoggingAppender.append(LoggingAppender.java:70)
    at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
[...]

I could understand a 403 or similar status code if it was an authentication error, but the Standard Environment is supposed to provide the service account, as well as automatically grant the Logs Writer role.

I'm kind of stumped here. Is there any way to have my application logs in the same place as the rest of my request logs, in the regular request_log?

[1] https://cloud.google.com/logging/docs/setup/java#logback_appender_for

score 1 · Answer 1 · answered Nov 19 '19 at 20:59

You should check out this example that does JSON logging with logback! The key element is that it includes the Trace ID so that the message correlates with the request log.

From the sample:

// Build structured log messages as an object.
Object globalLogFields = null;
// Add log correlation to nest all log messages beneath request log in Log Viewer.
String traceHeader = req.headers("x-cloud-trace-context");
if (traceHeader != null && project != null) {
  String trace = traceHeader.split("/")[0];
  globalLogFields =
      kv(
          "logging.googleapis.com/trace",
          String.format("projects/%s/traces/%s", project, trace));
}
// Create a structured log entry using key value pairs.
logger.error(
    "This is the default display field.",
    kv("component", "arbitrary-property"),
    kv("severity", "NOTICE"),
    globalLogFields);

That's _one step_ closer to what I'm looking to achieve, but it's still not putting the log lines in the same entry as the request. Not even when I add a field like `StructuredArgument logNameField = kv("logging.googleapis.com/logName", String.format("projects/%s/logs/%s", project, "appengine.googleapis.com%2Frequest_log"));`, they are still placed on the stdout. — Zalán Meggyesi, Nov 22 '19 at 19:04

Logging to App Engine request_log through Logback

1 Answers1