From 848d4bbe90cde76fa112bf5a91c90ae7a641fbe3 Mon Sep 17 00:00:00 2001 From: sebright Date: Mon, 1 Oct 2018 22:45:09 -0700 Subject: [PATCH] adservice: enable structured logging and OpenCensus log correlation (#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 #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 (https://github.com/GoogleCloudPlatform/fluent-plugin-google-cloud/issues/239, https://github.com/GoogleCloudPlatform/fluent-plugin-google-cloud/pull/260). This commit also upgrades OpenCensus to 0.16.1 in order to use opencensus-contrib-log-correlation-log4j2. --- src/adservice/build.gradle | 15 +++++++++--- .../src/main/java/hipstershop/AdService.java | 13 +++++----- .../java/hipstershop/AdServiceClient.java | 15 ++++++------ src/adservice/src/main/resources/log4j2.xml | 24 +++++++++++++++++++ 4 files changed, 51 insertions(+), 16 deletions(-) create mode 100644 src/adservice/src/main/resources/log4j2.xml diff --git a/src/adservice/build.gradle b/src/adservice/build.gradle index 2c6bce7..11e1be4 100644 --- a/src/adservice/build.gradle +++ b/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,6 +111,8 @@ 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) { @@ -113,6 +120,8 @@ task adServiceClient(type: CreateStartScripts) { 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') { diff --git a/src/adservice/src/main/java/hipstershop/AdService.java b/src/adservice/src/main/java/hipstershop/AdService.java index dfb1e40..9ba3329 100644 --- a/src/adservice/src/main/java/hipstershop/AdService.java +++ b/src/adservice/src/main/java/hipstershop/AdService.java @@ -50,11 +50,12 @@ import java.util.HashMap; 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 class AdService { 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,7 +219,7 @@ public class AdService { .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 { @@ -226,7 +227,7 @@ public class AdService { 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()); } } } diff --git a/src/adservice/src/main/java/hipstershop/AdServiceClient.java b/src/adservice/src/main/java/hipstershop/AdServiceClient.java index df6df07..a269a4c 100644 --- a/src/adservice/src/main/java/hipstershop/AdServiceClient.java +++ b/src/adservice/src/main/java/hipstershop/AdServiceClient.java @@ -38,13 +38,14 @@ import io.opencensus.trace.Tracing; 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 class AdServiceClient { 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 @@ public class AdServiceClient { 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,7 +157,7 @@ public class AdServiceClient { .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 { @@ -164,7 +165,7 @@ public class AdServiceClient { 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()); } } } diff --git a/src/adservice/src/main/resources/log4j2.xml b/src/adservice/src/main/resources/log4j2.xml new file mode 100644 index 0000000..f050ded --- /dev/null +++ b/src/adservice/src/main/resources/log4j2.xml @@ -0,0 +1,24 @@ + + + + + + + + + + + + + + + + + + + + + + +