Sets trace ID in log entries correctly (#683)

Adds a new logging enhancer that sets the right field for the log
entries to be linkable from a trace, in the Google Cloud Console.
Also updates Trace code sample to show this capability.

Fixes #664

spring-cloud-gcp-autoconfigure/src/main/java/org/springframework/cloud/gcp/autoconfigure/logging/LoggingWebMvcConfigurer.java

@@ -20,6 +20,7 @@
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.CompositeTraceIdExtractor;
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.XCloudTraceIdExtractor;
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.ZipkinTraceIdExtractor;
+import org.springframework.cloud.gcp.core.GcpProjectIdProvider;
 import org.springframework.context.annotation.Configuration;
 import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
 import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
@@ -44,14 +45,16 @@ public class LoggingWebMvcConfigurer implements WebMvcConfigurer {
 	 * a {@link TraceIdLoggingWebMvcInterceptor} is used with the trace ID extractor described above.
 	 */
 	public LoggingWebMvcConfigurer(
-			@Autowired(required = false) TraceIdLoggingWebMvcInterceptor interceptor) {
+			@Autowired(required = false) TraceIdLoggingWebMvcInterceptor interceptor,
+			GcpProjectIdProvider projectIdProvider) {
 		if (interceptor != null) {
 			this.interceptor = interceptor;
 		}
 		else {
 			this.interceptor = new TraceIdLoggingWebMvcInterceptor(
 					new CompositeTraceIdExtractor(
-							new XCloudTraceIdExtractor(), new ZipkinTraceIdExtractor()));
+							new XCloudTraceIdExtractor(), new ZipkinTraceIdExtractor()),
+					projectIdProvider);
 		}
 	}
 

spring-cloud-gcp-autoconfigure/src/main/java/org/springframework/cloud/gcp/autoconfigure/logging/StackdriverLoggingAutoConfiguration.java

@@ -27,6 +27,7 @@
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.TraceIdExtractorType;
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.XCloudTraceIdExtractor;
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.ZipkinTraceIdExtractor;
+import org.springframework.cloud.gcp.core.GcpProjectIdProvider;
 import org.springframework.context.annotation.Bean;
 import org.springframework.context.annotation.Configuration;
 import org.springframework.context.annotation.Import;
@@ -45,8 +46,9 @@ public class StackdriverLoggingAutoConfiguration {
 	@Bean
 	@ConditionalOnMissingBean
 	public TraceIdLoggingWebMvcInterceptor loggingWebMvcInterceptor(
-			TraceIdExtractor extractor) {
-		return new TraceIdLoggingWebMvcInterceptor(extractor);
+			TraceIdExtractor extractor,
+			GcpProjectIdProvider projectIdProvider) {
+		return new TraceIdLoggingWebMvcInterceptor(extractor, projectIdProvider);
 	}
 
 	@Bean

spring-cloud-gcp-autoconfigure/src/main/java/org/springframework/cloud/gcp/autoconfigure/logging/TraceIdLoggingEnhancer.java

@@ -0,0 +1,55 @@
+/*
+ *  Copyright 2018 original author or authors.
+ *
+ *  Licensed under the Apache License, Version 2.0 (the "License");
+ *  you may not use this file except in compliance with the License.
+ *  You may obtain a copy of the License at
+ *
+ *       http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *  Unless required by applicable law or agreed to in writing, software
+ *  distributed under the License is distributed on an "AS IS" BASIS,
+ *  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *  See the License for the specific language governing permissions and
+ *  limitations under the License.
+ */
+
+package org.springframework.cloud.gcp.autoconfigure.logging;
+
+import com.google.cloud.logging.LogEntry;
+import com.google.cloud.logging.LoggingEnhancer;
+
+/**
+ * Adds the trace ID to the logging entry, in its correct format to be displayed in the Logs viewer.
+ *
+ * @author João André Martins
+ */
+public class TraceIdLoggingEnhancer implements LoggingEnhancer {
+
+	private static final ThreadLocal<String> traceId = new ThreadLocal<>();
+
+	public static void setCurrentTraceId(String projectId, String id) {
+		if (id == null) {
+			traceId.remove();
+		}
+		else {
+			traceId.set("projects/" + projectId + "/traces/" + id);
+		}
+	}
+
+	/**
+	 * Returns the trace ID in the "projects/[MY_PROJECT_ID]/traces/[MY_TRACE_ID]".
+	 * @return the trace ID in the "projects/[MY_PROJECT_ID]/traces/[MY_TRACE_ID]"
+	 */
+	public static String getCurrentTraceId() {
+		return traceId.get();
+	}
+
+	@Override
+	public void enhanceLogEntry(LogEntry.Builder builder) {
+		String traceId = getCurrentTraceId();
+		if (traceId != null) {
+			builder.setTrace(traceId);
+		}
+	}
+}

spring-cloud-gcp-autoconfigure/src/main/java/org/springframework/cloud/gcp/autoconfigure/logging/TraceIdLoggingWebMvcInterceptor.java

@@ -20,18 +20,17 @@
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
-import com.google.cloud.logging.TraceLoggingEnhancer;
-
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.TraceIdExtractor;
+import org.springframework.cloud.gcp.core.GcpProjectIdProvider;
 import org.springframework.util.Assert;
 import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;
 
 /**
  * {@link org.springframework.web.servlet.HandlerInterceptor} that extracts the request
  * trace ID from the "x-cloud-trace-context" HTTP header and stores it in a thread-local
- * using {@link TraceLoggingEnhancer#setCurrentTraceId}.
+ * using {@link TraceIdLoggingEnhancer#setCurrentTraceId}.
  *
- * <p>The {@link TraceLoggingEnhancer} can then be used in a logging appender to add the
+ * <p>The {@link TraceIdLoggingEnhancer} can then be used in a logging appender to add the
  * trace ID metadata to log messages.
  *
  * @author Mike Eltsufin
@@ -41,9 +40,14 @@ public class TraceIdLoggingWebMvcInterceptor extends HandlerInterceptorAdapter {
 
 	private final TraceIdExtractor traceIdExtractor;
 
-	public TraceIdLoggingWebMvcInterceptor(TraceIdExtractor extractor) {
+	private final GcpProjectIdProvider projectIdProvider;
+
+	public TraceIdLoggingWebMvcInterceptor(TraceIdExtractor extractor,
+			GcpProjectIdProvider projectIdProvider) {
 		Assert.notNull(extractor, "A valid trace id extractor is required.");
+		Assert.notNull(projectIdProvider, "A valid project ID provider is required.");
 		this.traceIdExtractor = extractor;
+		this.projectIdProvider = projectIdProvider;
 	}
 
 	public TraceIdExtractor getTraceIdExtractor() {
@@ -55,7 +59,8 @@ public boolean preHandle(HttpServletRequest req,
 			HttpServletResponse resp, Object handler) throws Exception {
 		String traceId = this.traceIdExtractor.extractTraceIdFromRequest(req);
 		if (traceId != null) {
-			TraceLoggingEnhancer.setCurrentTraceId(traceId);
+			TraceIdLoggingEnhancer.setCurrentTraceId(
+					this.projectIdProvider.getProjectId(), traceId);
 		}
 		return true;
 	}
@@ -65,6 +70,6 @@ public void afterCompletion(HttpServletRequest httpServletRequest,
 			HttpServletResponse httpServletResponse, Object handler, Exception e) throws Exception {
 		// Note: the thread-local is currently not fully cleared, but just set to null
 		// See: https://github.com/GoogleCloudPlatform/google-cloud-java/issues/2746
-		TraceLoggingEnhancer.setCurrentTraceId(null);
+		TraceIdLoggingEnhancer.setCurrentTraceId(this.projectIdProvider.getProjectId(), null);
 	}
 }

spring-cloud-gcp-autoconfigure/src/main/resources/org/springframework/cloud/gcp/autoconfigure/logging/logback-appender.xml

@@ -11,7 +11,7 @@ Stackdriver appender logback configuration provided for import.
 
   <appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
     <log>${STACKDRIVER_LOG_NAME}</log> <!-- Optional : default java.log -->
-    <enhancer>com.google.cloud.logging.TraceLoggingEnhancer</enhancer> <!-- Optional -->
+    <enhancer>org.springframework.cloud.gcp.autoconfigure.logging.TraceIdLoggingEnhancer</enhancer>
     <flushLevel>${STACKDRIVER_LOG_FLUSH_LEVEL}</flushLevel> <!-- Optional : default ERROR -->
   </appender>
 </included>

spring-cloud-gcp-autoconfigure/src/test/java/org/springframework/cloud/gcp/autoconfigure/logging/LoggingWebMvcConfigurerTests.java

@@ -39,7 +39,8 @@ public class LoggingWebMvcConfigurerTests {
 
 	@Test
 	public void testAddInterceptors() {
-		LoggingWebMvcConfigurer adapter = new LoggingWebMvcConfigurer(this.interceptor);
+		LoggingWebMvcConfigurer adapter =
+				new LoggingWebMvcConfigurer(this.interceptor, () -> "remission");
 		TestInterceptorRegistry registry = new TestInterceptorRegistry();
 
 		adapter.addInterceptors(registry);

spring-cloud-gcp-autoconfigure/src/test/java/org/springframework/cloud/gcp/autoconfigure/logging/StackdriverLoggingAutoConfigurationTests.java

@@ -22,6 +22,7 @@
 
 import org.springframework.boot.autoconfigure.AutoConfigurations;
 import org.springframework.boot.test.context.runner.WebApplicationContextRunner;
+import org.springframework.cloud.gcp.autoconfigure.core.GcpContextAutoConfiguration;
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.CompositeTraceIdExtractor;
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.TraceIdExtractor;
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.TraceIdExtractorType;
@@ -39,7 +40,9 @@ public class StackdriverLoggingAutoConfigurationTests {
 	private WebApplicationContextRunner contextRunner =
 			new WebApplicationContextRunner()
 					.withConfiguration(
-							AutoConfigurations.of(StackdriverLoggingAutoConfiguration.class));
+							AutoConfigurations.of(
+									StackdriverLoggingAutoConfiguration.class,
+									GcpContextAutoConfiguration.class));
 
 	@Test
 	public void testDisabledConfiguration() {

spring-cloud-gcp-autoconfigure/src/test/java/org/springframework/cloud/gcp/autoconfigure/logging/TraceIdLoggingWebMvcInterceptorTests.java

@@ -16,7 +16,6 @@
 
 package org.springframework.cloud.gcp.autoconfigure.logging;
 
-import com.google.cloud.logging.TraceLoggingEnhancer;
 import org.junit.Test;
 
 import org.springframework.cloud.gcp.autoconfigure.logging.extractors.XCloudTraceIdExtractor;
@@ -39,26 +38,27 @@ public class TraceIdLoggingWebMvcInterceptorTests {
 	private static final String TRACE_ID_HEADER = "X-CLOUD-TRACE-CONTEXT";
 
 	private TraceIdLoggingWebMvcInterceptor interceptor =
-			new TraceIdLoggingWebMvcInterceptor(new XCloudTraceIdExtractor());
+			new TraceIdLoggingWebMvcInterceptor(new XCloudTraceIdExtractor(), () -> "remission");
 
 	@Test
 	public void testPreHandle() throws Exception {
 		MockHttpServletRequest request = new MockHttpServletRequest();
 		request.addHeader(TRACE_ID_HEADER, TEST_TRACE_ID_WITH_SPAN);
 
-		TraceLoggingEnhancer.setCurrentTraceId(null);
+		TraceIdLoggingEnhancer.setCurrentTraceId("remission", null);
 
 		this.interceptor.preHandle(request, null, null);
 
-		assertThat(TraceLoggingEnhancer.getCurrentTraceId(), is(TEST_TRACE_ID));
+		assertThat(TraceIdLoggingEnhancer.getCurrentTraceId(),
+				is("projects/remission/traces/" + TEST_TRACE_ID));
 	}
 
 	@Test
 	public void testAfterCompletion() throws Exception {
-		TraceLoggingEnhancer.setCurrentTraceId(TEST_TRACE_ID);
+		TraceIdLoggingEnhancer.setCurrentTraceId("remission", TEST_TRACE_ID);
 
 		this.interceptor.afterCompletion(null, null, null, null);
 
-		assertThat(TraceLoggingEnhancer.getCurrentTraceId(), nullValue());
+		assertThat(TraceIdLoggingEnhancer.getCurrentTraceId(), nullValue());
 	}
 }

spring-cloud-gcp-autoconfigure/src/test/java/org/springframework/cloud/gcp/autoconfigure/logging/it/StackdriverLoggingIntegrationTests.java

@@ -84,23 +84,23 @@ public void test() throws InterruptedException, IOException {
 		Logging logClient = LoggingOptions.newBuilder()
 				.setCredentials(credentialsProvider.getCredentials())
 				.build().getService();
-		GcpProjectIdProvider projectIdProvider = this.projectIdProvider;
 		Page<LogEntry> page;
 		int pageSize = 0;
 		int counter = 0;
 		do {
 			Thread.sleep(100);
 			page = logClient.listLogEntries(
 					Logging.EntryListOption.filter("textPayload:\"#$%^&" + NOW + "\" AND"
-							+ " logName=\"projects/" + projectIdProvider.getProjectId()
+							+ " logName=\"projects/" + this.projectIdProvider.getProjectId()
 							+ "/logs/spring.log\""));
 			for (LogEntry entry : page.getValues()) {
 				pageSize++;
 			}
 		} while (pageSize == 0 && counter++ < 20);
 		assertThat(pageSize).isEqualTo(1);
-		assertThat(page.getValues().iterator().next().getLabels().get("trace_id"))
-				.isEqualTo("everything-zen");
+		assertThat(page.getValues().iterator().next().getTrace())
+				.isEqualTo("projects/" + this.projectIdProvider.getProjectId()
+						+ "/traces/everything-zen");
 	}
 
 	@RestController

spring-cloud-gcp-samples/spring-cloud-gcp-trace-sample/README.adoc

@@ -1,26 +1,16 @@
 = Spring Cloud GCP Trace Starter Example
 
-This sample application demonstrates using the
-link:../../spring-cloud-gcp-starters/spring-cloud-gcp-starter-trace[Spring Cloud GCP Trace Starter] in your code.
+This sample application demonstrates using the link:../../spring-cloud-gcp-starters/spring-cloud-gcp-starter-trace[Spring Cloud GCP Trace Starter] in your code.
 
-You can read about the Spring Boot Starter for Stackdriver Trace in more detail at the
-link:../../spring-cloud-gcp-docs/src/main/asciidoc/trace.adoc[Spring Cloud GCP Reference Document
-Stackdriver Trace section].
+You can read about the Spring Boot Starter for Stackdriver Trace in more detail at the link:../../spring-cloud-gcp-docs/src/main/asciidoc/trace.adoc[Spring Cloud GCP Reference Document Stackdriver Trace section].
 
 == Setup & Configuration
 1. Create a Google Cloud Platform Project
-1. https://cloud.google.com/docs/authentication/getting-started#creating_the_service_account[Create a service account]
-with Trace Append permission. Furnish a new JSON key and then set the credentials using the
-`GOOGLE_APPLICATION_CREDENTIALS` environment variable or
-link:../../spring-cloud-gcp-starters/spring-cloud-gcp-starter/README.adoc[using GCP Starter Core properties].
+2. https://cloud.google.com/docs/authentication/getting-started#creating_the_service_account[Create a service account] with Trace Append permission. Furnish a new JSON key and then set the credentials using the `GOOGLE_APPLICATION_CREDENTIALS` environment variable or link:../../spring-cloud-gcp-starters/spring-cloud-gcp-starter/README.adoc[using GCP Starter Core properties].
 +
-Alternatively, if you have the https://cloud.google.com/sdk/[Google Cloud SDK] installed and
-initialized and are logged in with
-https://developers.google.com/identity/protocols/application-default-credentials[application
-default credentials], you can skip this step since Spring Cloud GCP will auto-discover those
-settings for you.
+Alternatively, if you have the https://cloud.google.com/sdk/[Google Cloud SDK] installed and initialized and are logged in with https://developers.google.com/identity/protocols/application-default-credentials[application default credentials], you can skip this step since Spring Cloud GCP will auto-discover those settings for you.
 
-1. Enable the https://console.cloud.google.com/apis/api/cloudtrace.googleapis.com/overview[Stackdriver Trace API]
+3. Enable the https://console.cloud.google.com/apis/api/cloudtrace.googleapis.com/overview[Stackdriver Trace API]
 
 == Run the Example
 Run the example from Maven:
@@ -30,14 +20,12 @@ $ mvn spring-boot:run
 ----
 
 Browse to `http://localhost:8080`. This will trigger the `ExampleController.work()` method,
-which in turn will call other services, and also a remote RESTful call to `ExampleController.meet()`
-method.
+which in turn will call other services, and also a remote RESTful call to `ExampleController.meet()` method.
 
-To see the traces, navigate to Stackdriver Trace console's
-https://console.cloud.google.com/traces/traces[Trace List] view.
+To see the traces, navigate to Stackdriver Trace console's https://console.cloud.google.com/traces/traces[Trace List] view.
 You should see the trace information in detail.
+Additionally, if you logged in with the Google Cloud SDK or have the `GOOGLE_CLOUD_PROJECT` environment variable set to your GCP project ID, you can also click the `View` link in front of the `Details` -> `Log` to view the log entries related to that trace ID.
 
-Note that the trace transmission delay default value is 10 seconds, so it can take a little
-while for the traces to show up in the Trace List page.
+Note that the trace transmission delay default value is 10 seconds, so it can take a little while for the traces to show up in the Trace List page.
 You can shorten this delay using the `spring.cloud.gcp.trace.scheduled-delay-seconds` property.
 

spring-cloud-gcp-samples/spring-cloud-gcp-trace-sample/pom.xml

@@ -24,5 +24,10 @@
             <groupId>org.springframework.cloud</groupId>
             <artifactId>spring-cloud-gcp-starter-trace</artifactId>
         </dependency>
+
+        <dependency>
+            <groupId>org.springframework.cloud</groupId>
+            <artifactId>spring-cloud-gcp-starter-logging</artifactId>
+        </dependency>
     </dependencies>
 </project>

spring-cloud-gcp-samples/spring-cloud-gcp-trace-sample/src/main/resources/logback-spring.xml

@@ -0,0 +1,12 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration>
+    <include resource="org/springframework/cloud/gcp/autoconfigure/logging/logback-appender.xml" />
+    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
+    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
+
+    <root level="INFO">
+        <!-- If running in GCP, remove the CONSOLE appender otherwise logs will be duplicated. -->
+        <appender-ref ref="CONSOLE"/>
+        <appender-ref ref="STACKDRIVER" />
+    </root>
+</configuration>