Skip to content
This repository has been archived by the owner on Jan 19, 2022. It is now read-only.

Sets trace ID in log entries correctly #683

Merged
merged 5 commits into from
May 17, 2018
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -0,0 +1,54 @@
/*
* 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;

import org.springframework.cloud.gcp.core.DefaultGcpProjectIdProvider;

/**
* 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 id) {
if (id == null) {
traceId.remove();
}
else {
traceId.set(id);
}
}

public static String getTraceId() {
return traceId.get();
}

@Override
public void enhanceLogEntry(LogEntry.Builder builder) {
String projectId = new DefaultGcpProjectIdProvider().getProjectId();
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If projectId is empty or null, there is really no suitable alternative, so it's safe if the final result is projects//traces/traceId or projects/null/traces/traceId.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it really safe to call here new DefaultGcpProjectIdProvider()? What if I use fully different projectId strategy in my project?

May we somehow workaround with the system property or make that setCurrentTraceId aware about the projectId as well?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Totally agree we should be doing this because the devsite mentions this format (https://cloud.google.com/trace/docs/viewing-details#log_entries) . But it makes me wonder why that other TraceLoggingEnhancer we were using even exists? the "trace_id" label that other one uses isn't mentioned in that devsite link at all... Should we set both ?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If there's no harm in doing so, I think we should do both. In that case I think you could even extend TraceLoggingEnhancer from the client lib and just override that single method.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I opened a new issue in google-cloud-java so they fix their current implementation. googleapis/google-cloud-java#3280

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We really only need the trace ID in one place, it's not being used for anything in labels.trace_id.
Probably better not to add any more complexity where it's not necessary.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sounds good to me

String traceId = getTraceId();
if (traceId != null) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks like if traceId == null, the projectId is redundant, therefore we even don't need to create a DefaultGcpProjectIdProvider instance in that case.

Just suggestion for minor optimization...

builder.setTrace("projects/" + projectId + "/traces/" + traceId);
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -20,18 +20,16 @@
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.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
Expand All @@ -55,7 +53,7 @@ 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(traceId);
}
return true;
}
Expand All @@ -65,6 +63,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(null);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -46,19 +45,19 @@ public void testPreHandle() throws Exception {
MockHttpServletRequest request = new MockHttpServletRequest();
request.addHeader(TRACE_ID_HEADER, TEST_TRACE_ID_WITH_SPAN);

TraceLoggingEnhancer.setCurrentTraceId(null);
TraceIdLoggingEnhancer.setCurrentTraceId(null);

this.interceptor.preHandle(request, null, null);

assertThat(TraceLoggingEnhancer.getCurrentTraceId(), is(TEST_TRACE_ID));
assertThat(TraceIdLoggingEnhancer.getTraceId(), is(TEST_TRACE_ID));
}

@Test
public void testAfterCompletion() throws Exception {
TraceLoggingEnhancer.setCurrentTraceId(TEST_TRACE_ID);
TraceIdLoggingEnhancer.setCurrentTraceId(TEST_TRACE_ID);

this.interceptor.afterCompletion(null, null, null, null);

assertThat(TraceLoggingEnhancer.getCurrentTraceId(), nullValue());
assertThat(TraceIdLoggingEnhancer.getTraceId(), nullValue());
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
30 changes: 9 additions & 21 deletions spring-cloud-gcp-samples/spring-cloud-gcp-trace-sample/README.adoc
Original file line number Diff line number Diff line change
@@ -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:
Expand All @@ -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.
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is really the only addition here. The rest is just putting sentences in the same line.


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.

Original file line number Diff line number Diff line change
Expand Up @@ -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>
Original file line number Diff line number Diff line change
@@ -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>