Spring Boot 3 DispatcherServlet not logging traceId (Impact on Error logging)

[santhosh-kumar3]

TraceId and SpanId are not getting logged by spring boot DispatcherServlet which also affecting error logging.

Any exception that is handled by spring (unhandled application exceptions/errors) logs stacktrace and this stacktrace doesn't contain traceId

How to reproduce:

1. Spring boot 2 sleuth distributed tracing demo application:
   https://github.com/sanintel3/spring-boot-2-mvc
   Versions:
   Java 17
   Spring boot: 2.7.17
   Gradle: 8.4

Success scenario logs:

2023-11-07 17:16:14.808  INFO [,**e8bfe5c6ea2019ff,e8bfe5c6ea2019ff**] 61615 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-11-07 17:16:14.809  INFO [,**e8bfe5c6ea2019ff,e8bfe5c6ea2019ff**] 61615 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2023-11-07 17:16:14.810  INFO [,**e8bfe5c6ea2019ff,e8bfe5c6ea2019ff**] 61615 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
2023-11-07 17:16:14.836  INFO [,**e8bfe5c6ea2019ff,e8bfe5c6ea2019ff**] 61615 --- [nio-8080-exec-1] com.example.demo.GreetingController      : Greeting Called

Error scenario logs:

2023-11-07 17:17:59.360 ERROR [,**7ff8da748799b55e,7ff8da748799b55e**] 61973 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.IllegalArgumentException: Greeting Failed] with root cause
java.lang.IllegalArgumentException: Greeting Failed
        at com.example.demo.GreetingController.greeting(GreetingController.java:24) ~[main/:na]

2. Spring boot 3 micrometer distributed tracing demo application:
   https://github.com/sanintel3/spring-boot-3-mvc
   Versions:
   Java 17
   Spring boot: 3.1.5
   Gradle: 8.4

Success scenario logs:

2023-11-07T17:44:56.720Z  INFO [,,] 67689 --- [nio-8081-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet' (**As you can see traceId and spanId are empty**)
2023-11-07T17:44:56.720Z  INFO [,,] 67689 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet' (**As you can see traceId and spanId are empty**)
2023-11-07T17:44:56.722Z  INFO [,,] 67689 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms (**As you can see traceId and spanId are empty**)
2023-11-07T17:44:56.763Z  INFO [,654a7798297a9c1942cbd8c65de67eb0,42cbd8c65de67eb0] 67689 --- [nio-8081-exec-1] c.e.springboot3mvc.GreetingController    : Greeting Called (**logs written by application is having traceId and spanId though**)

Error scenario logs:

2023-11-07T17:45:34.375Z ERROR [,,] 67689 --- [nio-8081-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: (**As you can see traceId and spanId are empty**)java.lang.IllegalArgumentException: Greeting Failed] with root cause
java.lang.IllegalArgumentException: Greeting Failed
        at com.example.demo.GreetingController.greeting(GreetingController.java:24) ~[main/:na]

As shown above with spring boot 3.1.5 micrometer distributed tracing DispatcherServlet is not logging traceId and spanId which is having an impact on error logging as well (which is more critical for debugging any production issues)

[bclozel]

I'm not sure I understand what observation should be going on during the Servlet infrastructure setup. There is no incoming request since the server is not started yet. Why should there be a trace id in this case?

As for exceptions not handled by the Spring web framework, those are bubbling up to the Servlet container and are handled by Tomcat itself. This is too low level for a Spring instrumentation. This has been discussed in spring-projects/spring-framework#29398 and documented here.

Micrometer might provide a Tomcat Valve for instrumentation in the future but you would need to disable web observations at the Spring level to not get duplicates.

[santhosh-kumar3]

@bclozel, Thanks for the response, I did clearly state the logs for spring boot 2 and 3, as you might have noticed, spring-boot-2 is logging the traceId where as boot-3 is not logging it for both success and error scenarios. For later case i.e. error scenario servlet is initialized and traceId is populated by applicatin logs however when exception is not handled by application not sure who handles that whether spring framework or tomcat, but traceId is missing in that as well

[bclozel]

@sanintel3 it seems you're re-stating your first comment without replying to my question.

Anyway, I think your concerns are covered by my previous comment. While it is a change of behavior, the Spring Cloud Sleuth approach had many issues and this is why the team chose a different route for instrumenting applications. You can follow micrometer-metrics/micrometer#3777 if you'd like to instrument your application at a lower level with Tomcat.

[santhosh-kumar3]

In success scenario, agreed it's not important to log traceId during initialization logs but there is a change in behaviour as you mentioned in the previous comment between sleuth and micrometer how this is handled and it make sense, but for error scenario I don't understand whether a fix will be provided by container or not. However, we may need to go with workaround suggested in the other ticket. Thanks for looking into it

[fischermatte]

@bclozel Is there any suggestion from spring how to deal with this? Any workaround? Whenever we have exceptions for example within in a filter, we just get this log:

2024-02-21 12:40:48,895 ERROR [my-app,,] o.a.c.c.C.[.[.[.[dispatcherServlet] - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception

Trace-id and span-id is always missing. Tested with spring boot 3.2.2.