From 4203566d87434e2cb65fbbb9b90fd92bac447f2e Mon Sep 17 00:00:00 2001
From: Marcin Grzejszczak <mgrzejszczak@pivotal.io>
Date: Fri, 3 Nov 2017 22:41:50 +0100
Subject: [PATCH] Exceptions that escape SpringMVC DispatcherServlet should be
 logged with trace & span IDs

without this change any exception that is not caught by a filter, get caught and logged by server's internals (e.g. Tomcat's Valve). To make the Valve log the exception together with the tracing information we would have to allow the tracing context remain in the thread after TraceFilter gets executed. That is problematic cause we're polluting the ThreadLocal and would have to assume that some component will eventually clear the context.

with this change we're trying to solve the issue from a different angle. Whenever an uncaught exception is thrown, we are already catching it in the `catch(...) {}` clause. It's enough to just log it at the error level and that way, regardless of the underlying server implementation (Tomcat, Undertow) we will log the uncaught exception and rethrow it.

fixes #714
---
 .../sleuth/instrument/web/TraceFilter.java    |  3 +++
 .../web/TraceFilterWebIntegrationTests.java   | 22 +++++++++++++++----
 2 files changed, 21 insertions(+), 4 deletions(-)

diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java
index 6c6e087e0..fa7af77e7 100644
--- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java
+++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java
@@ -165,6 +165,9 @@ public class TraceFilter extends GenericFilterBean {
 		} catch (Throwable e) {
 			exception = e;
 			errorParser().parseErrorTags(tracer().getCurrentSpan(), e);
+			if (log.isErrorEnabled()) {
+				log.error("Uncaught exception thrown", e);
+			}
 			throw e;
 		} finally {
 			if (isAsyncStarted(request) || request.isAsyncStarted()) {
diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterWebIntegrationTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterWebIntegrationTests.java
index 5e676bb30..0678e61e8 100644
--- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterWebIntegrationTests.java
+++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterWebIntegrationTests.java
@@ -16,18 +16,20 @@
 
 package org.springframework.cloud.sleuth.instrument.web;
 
-import static org.assertj.core.api.Assertions.fail;
-import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
-
 import java.io.IOException;
+import java.util.Arrays;
+import java.util.List;
+import java.util.stream.Collectors;
 
 import org.junit.After;
 import org.junit.Before;
+import org.junit.Rule;
 import org.junit.Test;
 import org.junit.runner.RunWith;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
 import org.springframework.boot.test.context.SpringBootTest;
+import org.springframework.boot.test.rule.OutputCapture;
 import org.springframework.cloud.sleuth.Sampler;
 import org.springframework.cloud.sleuth.Span;
 import org.springframework.cloud.sleuth.Tracer;
@@ -49,6 +51,9 @@ import org.springframework.web.client.DefaultResponseErrorHandler;
 import org.springframework.web.client.HttpClientErrorException;
 import org.springframework.web.client.RestTemplate;
 
+import static org.assertj.core.api.Assertions.fail;
+import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
+
 /**
  * @author Marcin Grzejszczak
  */
@@ -61,6 +66,7 @@ public class TraceFilterWebIntegrationTests {
 	@Autowired ArrayListSpanAccumulator accumulator;
 	@Autowired RestTemplate restTemplate;
 	@Autowired Environment environment;
+	@Rule  public OutputCapture capture = new OutputCapture();
 
 	@Before
 	@After
@@ -82,7 +88,15 @@ public class TraceFilterWebIntegrationTests {
 		then(new ListOfSpans(this.accumulator.getSpans()))
 				.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME,
 						"Request processing failed; nested exception is java.lang.RuntimeException: Throwing exception")
-				.hasRpcTagsInProperOrder();
+				.hasRpcTagsInProperOrder();// issue#714
+		Span span = this.accumulator.getSpans().get(0);
+		String hex = Span.idToHex(span.getTraceId());
+		String[] split = capture.toString().split("\n");
+		List<String> list = Arrays.stream(split).filter(s -> s.contains(
+				"Uncaught exception thrown"))
+				.filter(s -> s.contains("[bootstrap," + hex + "," + hex + ",true]"))
+				.collect(Collectors.toList());
+		then(list).isNotEmpty();
 	}
 
 	@Test