spring-boot icon indicating copy to clipboard operation
spring-boot copied to clipboard
verified publisher icon spring-projects

Lack of Trace and Span ID in certain flows

Open Jyosua opened this issue 2 months ago • 4 comments

I suspect this will be closed as a duplicate, but I've feel like I've read a hundred different, yet similar issues and the error handling documentation doesn't make the issue any clearer. Part of this is because of the search results being polluted by old Sleuth related information, but in this case I'm using Spring Boot 3.5.8 with Micrometer 1.6.0.

I've noticed in certain flows, such as an exception being raised and error logged by the default JWT Decoder (In Spring Security's OAuth2 default configuration, NimbusJwtDecoder) or the initial FilterChainProxy debug log when a secured endpoint is called, the Trace ID and Span ID are missing from logs despite the logger being configured to show them. In the JWT decoder example, if I replace the default decoder with a simple wrapper that manually logs a warning level message, the trace and span information will be included in that log, but the eventual error level log that will happen once it reaches the servlet will not have that information.

My consternation with this is that typically users of this framework are going to want to raise an Exception and have that be handled by the framework -- irrespective of if it's in a controller, filter, or other configuration. If the error log the framework writes in response to that doesn't have the Trace and Span IDs, it's much harder to track down related logs, so this doesn't seem like good default behavior and I would wager most web server frameworks don't behave like this. Anecdotally I can say the ones I've worked with don't.

I'd really like a resolution that allows me to just make a change in one place to uniformly ensure that logs (at a minimum error level logs) will have these IDs so long as they are the result of a request, but barring that, I'd at least like the documentation to describe the problem and workarounds in a way that doesn't require very deep understanding of the Spring internals. The way it's written right now is quite difficult to parse and honestly it doesn't quite seem to describe the solution I'm looking for.

I hope that doesn't come across as an unreasonable request, but I suspect that most users using Spring are doing so to make developing a backend easier. If they have to continually dig into the source code of the framework in order to understand the documentation, I don't think the documentation is doing its job well. I frequently feel like I run across problems like this that are much simpler to solve in other frameworks or just with servers written using the raw language APIs.

Jyosua avatar Dec 09 '25 09:12 Jyosua

I don't think it's unreasonable, but it's not quite actionable at the moment as I'm not 100% sure that I understand the situation that you're describing. I suspect that the observation for the request has been stopped by the time the logging occurs but that's just a somewhat educated guess. To help us to investigate further, please provide a minimal real-world example that reproduces the missing IDs.

wilkinsona avatar Dec 09 '25 09:12 wilkinsona

I'll see if I can setup a sample project tomorrow that reproduces it, but at least the JWT Decoder example should be reproducible by:

  1. Setup a new project using Spring Boot and Micrometer
  2. Setup Spring Security and configure using the OAuth2 Resource Server dependency
  3. Configure security.oauth2.resourceserver.jwt.jwk-set-uri to enable JWT support
  4. Configure logback appender to use [%X{traceId:-},%X{spanId:-}]
  5. Configure a simple Get endpoint to require authorization
  6. Call the endpoint with header: Authorization: Bearer invalidtoken

Jyosua avatar Dec 09 '25 10:12 Jyosua

I can't reproduce the behavior that you have described with Spring Boot 3.5.8. Making a request to a secure endpoint with an invalid token produces three DEBUG log messages, each of which includes the trace ID and span ID:

2025-12-09T13:46:19.523Z DEBUG 48864 --- [nio-8080-exec-1] [a53e54a51b6daff023c0d42511deeb82,0565e6f6d923a563] o.s.security.web.FilterChainProxy        : Securing GET /
2025-12-09T13:46:19.529Z DEBUG 48864 --- [nio-8080-exec-1] [a53e54a51b6daff023c0d42511deeb82,41bb31800e0a258b] o.s.s.o.s.r.a.JwtAuthenticationProvider  : Failed to authenticate since the JWT was invalid
2025-12-09T13:46:19.530Z DEBUG 48864 --- [nio-8080-exec-1] [a53e54a51b6daff023c0d42511deeb82,41bb31800e0a258b] o.s.s.authentication.ProviderManager     : Authentication failed with provider JwtAuthenticationProvider since An error occurred while attempting to decode the Jwt: Malformed token

We're going to need the sample project to make progress here.

wilkinsona avatar Dec 09 '25 13:12 wilkinsona

Okay I setup a project to reproduce the issue.

Here is the repo: https://github.com/Jyosua/spring-boot-tracing-issue-sample

Here's the error output:

2025-12-10 19:39:56.483 [http-nio-8080-exec-1] DEBUG [69394dfcd31030285186bfb54fda0eeb,5186bfb54fda0eeb] o.s.security.web.FilterChainProxy - Securing GET /
2025-12-10 19:39:56.488 [http-nio-8080-exec-1] ERROR [,] o.a.c.c.C.[.[.[.[dispatcherServlet] - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Filter execution threw an exception] with root cause
java.text.ParseException: example
	at com.example.demo.ErrorThrowingDecoder.decode(ErrorThrowingDecoder.kt:9)
	at org.springframework.security.oauth2.server.resource.authentication.JwtAuthenticationProvider.getJwt(JwtAuthenticationProvider.java:99)
	at org.springframework.security.oauth2.server.resource.authentication.JwtAuthenticationProvider.authenticate(JwtAuthenticationProvider.java:88)
	at org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:182)
	at org.springframework.security.authentication.ObservationAuthenticationManager.lambda$authenticate$1(ObservationAuthenticationManager.java:54)
	at io.micrometer.observation.Observation.observe(Observation.java:564)
	at org.springframework.security.authentication.ObservationAuthenticationManager.authenticate(ObservationAuthenticationManager.java:53)
	at org.springframework.security.oauth2.server.resource.web.authentication.BearerTokenAuthenticationFilter.doFilterInternal(BearerTokenAuthenticationFilter.java:144)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:241)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:228)
	at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:138)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:107)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:93)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:241)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:228)
	at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:138)
	at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90)
	at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:241)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:228)
	at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:138)
	at org.springframework.security.web.context.SecurityContextHolderFilter.doFilter(SecurityContextHolderFilter.java:82)
	at org.springframework.security.web.context.SecurityContextHolderFilter.doFilter(SecurityContextHolderFilter.java:69)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:241)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:228)
	at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:138)
	at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:62)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:241)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:228)
	at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:138)
	at org.springframework.security.web.session.DisableEncodeUrlFilter.doFilterInternal(DisableEncodeUrlFilter.java:42)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:241)
	at org.springframework.security.web.ObservationFilterChainDecorator$AroundFilterObservation$SimpleAroundFilterObservation.lambda$wrap$0(ObservationFilterChainDecorator.java:334)
	at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:225)
	at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:138)
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:233)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:191)
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113)
	at org.springframework.web.filter.ServletRequestPathFilter.doFilter(ServletRequestPathFilter.java:52)
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113)
	at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:74)
	at org.springframework.security.config.annotation.web.configuration.WebSecurityConfiguration$CompositeFilterChainProxy.doFilter(WebSecurityConfiguration.java:319)
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113)
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector.lambda$createCacheFilter$4(HandlerMappingIntrospector.java:267)
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113)
	at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:74)
	at org.springframework.security.config.annotation.web.configuration.WebMvcSecurityConfiguration$CompositeFilterChainProxy.doFilter(WebMvcSecurityConfiguration.java:240)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:362)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:278)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:138)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:138)
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:138)
	at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:110)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:138)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:138)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:165)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:88)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:113)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:83)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:72)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:399)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:903)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1774)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:973)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:491)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
	at java.base/java.lang.Thread.run(Thread.java:1583)
2025-12-10 19:39:56.491 [http-nio-8080-exec-1] DEBUG [,] o.s.security.web.FilterChainProxy - Securing GET /error
2025-12-10 19:39:56.492 [http-nio-8080-exec-1] DEBUG [69394dfcd31030285186bfb54fda0eeb,395dea3dde0f4ad7] o.s.s.w.a.AnonymousAuthenticationFilter - Set SecurityContextHolder to anonymous SecurityContext

You can see here that while Securing GET / has the trace and span info, Securing GET /error and the Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Filter execution threw an exception] with root cause java.text.ParseException: example logs do not.

For context of why this matters: We may need to parse the token headers for information before verifying a token signature, etc. If the token is malformed, a parse error may be thrown, but I'd imagine other people with other use cases might have other types of exceptions thrown.

Jyosua avatar Dec 10 '25 10:12 Jyosua

Thanks. As I suspected, this is happening because the logging is performed after the observation has been stopped.

I'd argue that the ErrorThrowingDecoder isn't fully compliant with the contract that it implements. Rather than throwing an arbitrary unchecked exception, it should throw some form of JwtException. A BadJwtException would seem ideal in this case as it's intended to indicate that a JWT is invalid in some way. Making this change results in only the three DEBUG messages that I shared above. This problem aside, I think that's preferable as it prevents someone from flooding the logs with error messages and large exception stack traces by making repeated requests with an invalid token. This, however, won't help in the general case.

More generally, the observation's been stopped because the exception has been thrown from within the filter chain and before Spring MVC's dispatcher servlet has been invoked. This means that the dispatcher servlet's usual error handling isn't available. As a result of the exception, the filter chain unwinds. This stops the observation and the exception reaches Tomcat at which point it's logged.

One way to avoid this would be to use a container-specific plug point to start and stop the observation. When using Tomcat, this would be a Valve. A notable downside of this approach is that behavior would then be inconsistent between embedded Tomcat and a war deployed to Tomcat. We'd also have to maintain a similar implementation for embedded Jetty. I'll discuss things with the team.

wilkinsona avatar Dec 10 '25 11:12 wilkinsona

Besides the exception hierarchy (something to be looked at in Spring Security), I think this shows the expected behavior. The trace Id is available within the scope of the observation as shows above. The main problem here is that this exception is not caught+handled within the observation. I can think of three change to fix this:

  1. make the observation filter catch and handle all exceptions. This is the wrong behavior in my opinion because Servlet filters do expect some exceptions to bubble up in the filter chain, and the observation filter itself would not know how to handle this exception for the HTTP response
  2. make Spring Security handle this exception. I'm not sure what's the expected behavior here. It could be that applications rely on that exception being handled by the Servlet container itself for the error pages support
  3. setting up the web observation at a lower level, as suggested by Andy. This means that the observations themselves will be more precise, but at the price of being not portable. Right now Spring Framework implements a Servlet filter for that, which is compatible with all Servlet containers. Going down this path means that we need to maintain in parallel specific implementations for Tomcat, Jetty and others. I don't think we have the bandwidth to do that. The Micrometer team did consider this in https://github.com/micrometer-metrics/micrometer/issues/3777 but I'm not sure this is going anywhere for the same reasons.

bclozel avatar Dec 10 '25 12:12 bclozel

I'd argue that the ErrorThrowingDecoder isn't fully compliant with the contract that it implements. Rather than throwing an arbitrary unchecked exception, it should throw some form of JwtException

This very heavily feels like a Java mentality vs Kotlin/modern exception handling mentality. I generally skew away from liberal use of try/catch and re-wrapping exceptions due to performance reasons (stack unwinding), i.e. the convention that exceptions should be exceptional. Ideally I want to be very defensive in my programming and only throw an exception when it really needs to be thrown and bubble up to a higher level. Someone calling the API with an invalid token seems like too frequent of a use case to really be exceptional.

That being said, this Parse exception was actually getting thrown by SignedJWT.parse() in my real project and I just sort of wrongly expected that either, since nimusds.jwt is heavily used by Spring, it would handle any exceptions that would typically come from those libraries or that the libraries wouldn't throw at all here and would return a null (the latter being ideal).

I can obviously fix this and handle it in the way that's intended, but I do feel like it's sort of forcing an archaic pattern, especially given a gradual push towards Kotlin.

In most server frameworks or home-grown server applications I've worked on, the flow from request processing to response is relatively linear or at least passes context information (traces, spans, etc.) alongside the request while the entire call chain processes it. At the top-most level, there is usually a catch-all catch as a last resort to be able to return an error response and log any of the relevant data, since there may be otherwise unhandled, unexpected exceptions. That's why I'm surprised this can even happen in Spring -- the jwtDecoder is being called as a direct result of a request, so even if it unexpectedly throws an exception, I would have expected this to still be traceable.

Jyosua avatar Dec 10 '25 13:12 Jyosua

or the initial FilterChainProxy debug log when a secured endpoint is called, the Trace ID and Span ID are missing from logs despite the logger

Just as an aside in case anyone reads this later. I did figure out why this happened. This one was because of the Filter ordering -- my MDC filter needed to be first, before anything else. If it was later than HighestOrder + 1, the trace and span would be missing from the initial spring security log like this.

Jyosua avatar Dec 10 '25 13:12 Jyosua

That being said, this Parse exception was actually getting thrown by SignedJWT.parse() in my real project and I just sort of wrongly expected that either, since nimusds.jwt is heavily used by Spring, it would handle any exceptions that would typically come from those libraries or that the libraries wouldn't throw at all here and would return a null (the latter being ideal).

Please open a Spring Security issue for this. There may be room for improvement in how it handles exceptions thrown from org.springframework.security.oauth2.jwt.JwtDecoder.decode(String) or, more generally, thrown anywhere within FilterChainProxy.doFilter.

wilkinsona avatar Dec 10 '25 13:12 wilkinsona

We discussed this today and we'd like to investigate what Tomcat- and Jetty-specific equivalents of ServerHttpObservationFilter would look like. In the case of Tomcat, it would be Valve. By plugging this in at the server level it will make timing information a little more accurate and will also increase the likelihood of exception logging including the trace and span ID. We'll have to assess whether or not the complexity of the implementations is worth it for these benefits.

wilkinsona avatar Dec 10 '25 16:12 wilkinsona