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]
- 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)
Comment From: 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 https://github.com/spring-projects/spring-framework/issues/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.
Comment From: 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
Comment From: 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 https://github.com/micrometer-metrics/micrometer/issues/3777 if you'd like to instrument your application at a lower level with Tomcat.
Comment From: 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
Comment From: 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.