adservice: enable structured logging and OpenCensus log correlation (GoogleCloudPlatform#59)

This commit enables OpenCensus log correlation using
opencensus-contrib-log-correlation-log4j2
(https://github.com/census-instrumentation/opencensus-java/tree/master/contrib/log_correlation/log4j2).
The library inserts the trace ID, span ID, and sampling decision into every
Log4j log event.  This commit includes other changes to make the tracing data
available in the logs, in a format that can be interpreted by the Stackdriver
Logging agent:

- Convert all adservice log statements from java.util.logging to Log4j.

- Specify a JSON format for Log4j output.  This is related to issue GoogleCloudPlatform#47.

- Add the trace ID, span ID, and sampling decision to the JSON format.  Trace
  ID and span ID use special keys that the Stackdriver Logging agent uses to
  populate the tracing data fields in the LogEntry uploaded to Stackdriver
  (https://cloud.google.com/logging/docs/agent/configuration#special_fields_in_structured_payloads).
  However, Stackdriver won't be able to link the traces and log entries until
  fluent-plugin-google-cloud can automatically format the trace ID with the
  format expected by Stackdriver
  (GoogleCloudPlatform/fluent-plugin-google-cloud#239,
  GoogleCloudPlatform/fluent-plugin-google-cloud#260).

This commit also upgrades OpenCensus to 0.16.1 in order to use
opencensus-contrib-log-correlation-log4j2.

Author: sebright2

src/adservice/build.gradle

@@ -25,8 +25,9 @@ repositories {
 group = "adservice"
 version = "0.1.0-SNAPSHOT" // CURRENT_OPENCENSUS_VERSION
 
-def opencensusVersion = "0.15.0" // LATEST_OPENCENSUS_RELEASE_VERSION
+def opencensusVersion = "0.16.1" // LATEST_OPENCENSUS_RELEASE_VERSION
 def grpcVersion = "1.15.0" // CURRENT_GRPC_VERSION
+def jacksonVersion = "2.9.6"
 def prometheusVersion = "0.3.0"
 
 tasks.withType(JavaCompile) {
@@ -52,9 +53,13 @@ dependencies {
                 "io.grpc:grpc-stub:${grpcVersion}",
                 "io.grpc:grpc-netty:${grpcVersion}",
                 "io.grpc:grpc-services:${grpcVersion}",
-                "io.prometheus:simpleclient_httpserver:${prometheusVersion}"
+                "io.prometheus:simpleclient_httpserver:${prometheusVersion}",
+                "org.apache.logging.log4j:log4j-core:2.11.1"
 
-        runtime "io.opencensus:opencensus-impl:${opencensusVersion}",
+        runtime "com.fasterxml.jackson.core:jackson-core:${jacksonVersion}",
+                "com.fasterxml.jackson.core:jackson-databind:${jacksonVersion}",
+                "io.opencensus:opencensus-contrib-log-correlation-log4j2:${opencensusVersion}",
+                "io.opencensus:opencensus-impl:${opencensusVersion}",
                 "io.netty:netty-tcnative-boringssl-static:2.0.8.Final"
     }
 }
@@ -106,13 +111,17 @@ task adService(type: CreateStartScripts) {
     applicationName = 'AdService'
     outputDir = new File(project.buildDir, 'tmp')
     classpath = jar.outputs.files + project.configurations.runtime
+    defaultJvmOpts =
+        ["-Dlog4j2.contextDataInjector=io.opencensus.contrib.logcorrelation.log4j2.OpenCensusTraceContextDataInjector"]
 }
 
 task adServiceClient(type: CreateStartScripts) {
     mainClassName = 'hipstershop.AdServiceClient'
     applicationName = 'AdServiceClient'
     outputDir = new File(project.buildDir, 'tmp')
     classpath = jar.outputs.files + project.configurations.runtime
+    defaultJvmOpts =
+        ["-Dlog4j2.contextDataInjector=io.opencensus.contrib.logcorrelation.log4j2.OpenCensusTraceContextDataInjector"]
 }
 
 applicationDistribution.into('bin') {

src/adservice/src/main/java/hipstershop/AdService.java

@@ -50,11 +50,12 @@
 import java.util.List;
 import java.util.Random;
 import java.util.concurrent.TimeUnit;
-import java.util.logging.Level;
-import java.util.logging.Logger;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.LogManager;
 
 public class AdService {
-  private static final Logger logger = Logger.getLogger(AdService.class.getName());
+  private static final Logger logger = LogManager.getLogger(AdService.class);
 
   private static final Tracer tracer = Tracing.getTracer();
 
@@ -139,7 +140,7 @@ public void getAds(AdRequest req, StreamObserver<AdResponse> responseObserver) {
         responseObserver.onNext(reply);
         responseObserver.onCompleted();
       } catch (StatusRuntimeException e) {
-        logger.log(Level.WARNING, "GetAds Failed", e.getStatus());
+        logger.log(Level.WARN, "GetAds Failed", e.getStatus());
         return;
       }
     }
@@ -218,15 +219,15 @@ public static void initStackdriver() {
                 .build());
       } catch (Exception e) {
         if (i==(maxAttempts-1)) {
-          logger.log(Level.WARNING, "Failed to register Stackdriver Exporter." +
+          logger.log(Level.WARN, "Failed to register Stackdriver Exporter." +
               " Tracing and Stats data will not reported to Stackdriver. Error message: " + e
               .toString());
         } else {
           logger.info("Attempt to register Stackdriver Exporter in " + sleepTime + " seconds ");
           try {
             Thread.sleep(TimeUnit.SECONDS.toMillis(sleepTime));
           } catch (Exception se) {
-            logger.log(Level.WARNING, "Exception while sleeping" + se.toString());
+            logger.log(Level.WARN, "Exception while sleeping" + se.toString());
           }
         }
       }

src/adservice/src/main/java/hipstershop/AdServiceClient.java

@@ -38,13 +38,14 @@
 import io.opencensus.trace.samplers.Samplers;
 import java.io.IOException;
 import java.util.concurrent.TimeUnit;
-import java.util.logging.Level;
-import java.util.logging.Logger;
 import javax.annotation.Nullable;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.LogManager;
 
 /** A simple client that requests ads from the Ads Service. */
 public class AdServiceClient {
-  private static final Logger logger = Logger.getLogger(AdServiceClient.class.getName());
+  private static final Logger logger = LogManager.getLogger(AdServiceClient.class);
 
   private static final Tracer tracer = Tracing.getTracer();
 
@@ -90,7 +91,7 @@ public void getAds(String contextKey) {
               CanonicalCode.valueOf(e.getStatus().getCode().name())
                   .toStatus()
                   .withDescription(e.getMessage()));
-      logger.log(Level.WARNING, "RPC failed: {0}", e.getStatus());
+      logger.log(Level.WARN, "RPC failed: {0}", e.getStatus());
       return;
     }
     for(Ad ads: response.getAdsList()) {
@@ -104,7 +105,7 @@ static int getPortOrDefaultFromArgs(String[] args, int index, int defaultPort) {
       try {
         portNumber = Integer.parseInt(args[index]);
       } catch (NumberFormatException e) {
-        logger.warning(
+        logger.warn(
             String.format("Port %s is invalid, use default port %d.", args[index], defaultPort));
       }
     }
@@ -156,15 +157,15 @@ public static void main(String[] args) throws IOException, InterruptedException
                   .build());
         } catch (Exception e) {
           if (i==(maxAttempts-1)) {
-            logger.log(Level.WARNING, "Failed to register Stackdriver Exporter." +
+            logger.log(Level.WARN, "Failed to register Stackdriver Exporter." +
                 " Tracing and Stats data will not reported to Stackdriver. Error message: " + e
                 .toString());
           } else {
             logger.info("Attempt to register Stackdriver Exporter in " + sleepTime + " seconds");
             try {
               Thread.sleep(TimeUnit.SECONDS.toMillis(sleepTime));
             } catch (Exception se) {
-              logger.log(Level.WARNING, "Exception while sleeping" + e.toString());
+              logger.log(Level.WARN, "Exception while sleeping" + e.toString());
             }
           }
         }

src/adservice/src/main/resources/log4j2.xml

@@ -0,0 +1,24 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<Configuration status="WARN">
+  <Appenders>
+    <Console name="STDOUT" target="SYSTEM_OUT">
+
+      <!-- This is a JSON format that can be read by the Stackdriver Logging agent. The trace and
+           span IDs are interpreted by Stackdriver, and "traceSampled" is a custom field. -->
+      <JsonLayout compact="true" eventEol="true">
+        <KeyValuePair key="logging.googleapis.com/trace" value="$${ctx:opencensusTraceId}"/>
+        <KeyValuePair key="logging.googleapis.com/spanId" value="$${ctx:opencensusSpanId}"/>
+        <KeyValuePair key="traceSampled" value="$${ctx:opencensusTraceSampled}"/>
+     </JsonLayout>
+
+    </Console>
+  </Appenders>
+  <Loggers>
+    <Logger name="io.grpc.netty" level="INFO"/>
+    <Logger name="io.netty" level="INFO"/>
+    <Logger name="sun.net" level="INFO"/>
+    <Root level="TRACE">
+      <AppenderRef ref="STDOUT"/>
+    </Root>
+  </Loggers>
+</Configuration>