Trace lost in error log

[wapkch]

Affects: 6.0.9

Let's say we have the following code:

@RestController
@SpringBootApplication
public class WebTracingLogDemoApplication {

    Logger logger = LoggerFactory.getLogger(WebTracingLogDemoApplication.class);

    public static void main(String[] args) {
        SpringApplication.run(WebTracingLogDemoApplication.class, args);
    }

    @GetMapping("/hello")
    public void hello() {
        logger.info("hello");
        throw new RuntimeException();
    }

}

application.properties:

logging.pattern.level=trace:%X{traceId:-} %5p

1. Start the application
2. Access http:localhost:8080/hello

The output log is as follows:

2023-06-15T14:29:22.778+08:00 trace:648aafc28d0219a11c28e4249e2a613d  INFO 32528 --- [nio-8080-exec-1] c.e.w.WebTracingLogDemoApplication       : hello
2023-06-15T14:29:22.781+08:00 trace: ERROR 32528 --- [nio-8080-exec-1] o.a.c.c.C.[.[. [/]. [dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.lang.RuntimeException] with root cause

java.lang.RuntimeException: null
	at com.example.webtracinglogdemo.WebTracingLogDemoApplication.hello(WebTracingLogDemoApplication.java:23) ~[main/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]

We can find the trace exists in the first line, but lost in the second line error log. This is different from spring 5.x's behavior, which trace won't be lost in this error log.

Sample:
https://github.com/wapkch/web-tracing-log-demo

[bclozel]

We can find the trace exists in the first line, but lost in the second line error log. This is different from spring 5.x's behavior, which trace won't be lost in this error log.

What do you mean? What were you using for tracing support? Spring Cloud Sleuth?

Sample:
https://github.com/wapkch/web-tracing-log-demo

The repository is empty.

[wapkch]

What do you mean? What were you using for tracing support? Spring Cloud Sleuth?

I'm using Micrometer for tracing support (Spring Boot 3)

The repository is empty.

Sorry, failed to push just now, now pushed. Please see again https://github.com/wapkch/web-tracing-log-demo

[wapkch]

After looking into it, i found that it was related to the FORWARD DispatcherType of the filter registration.

When using Spring Boot 2 with Spring Cloud Sleuth, DispatcherType.FORWARD is included in the DispatcherTypes:

@Bean
	FilterRegistrationBean traceWebFilter(BeanFactory beanFactory, SleuthWebProperties webProperties) {
		FilterRegistrationBean filterRegistrationBean = new FilterRegistrationBean(new LazyTracingFilter(beanFactory));
		filterRegistrationBean.setDispatcherTypes(DispatcherType.ASYNC, DispatcherType.ERROR, DispatcherType.FORWARD,
				DispatcherType.INCLUDE, DispatcherType.REQUEST);
		filterRegistrationBean.setOrder(webProperties.getFilterOrder());
		return filterRegistrationBean;
	}

When using Spring Boot 3 with Micrometer Tracing, DispatcherType.FORWARD is not included in the DispatcherTypes:

@Bean
	@ConditionalOnMissingFilterBean
	public FilterRegistrationBean<ServerHttpObservationFilter> webMvcObservationFilter(ObservationRegistry registry,
			ObjectProvider<ServerRequestObservationConvention> customConvention,
			ObjectProvider<WebMvcTagsProvider> customTagsProvider,
			ObjectProvider<WebMvcTagsContributor> contributorsProvider) {
		String name = httpRequestsMetricName(this.observationProperties, this.metricsProperties);
		ServerRequestObservationConvention convention = createConvention(customConvention.getIfAvailable(), name,
				customTagsProvider.getIfAvailable(), contributorsProvider.orderedStream().toList());
		ServerHttpObservationFilter filter = new ServerHttpObservationFilter(registry, convention);
		FilterRegistrationBean<ServerHttpObservationFilter> registration = new FilterRegistrationBean<>(filter);
		registration.setOrder(Ordered.HIGHEST_PRECEDENCE + 1);
		registration.setDispatcherTypes(DispatcherType.REQUEST, DispatcherType.ASYNC);
		return registration;
	}

So, i think it should be an issue of Spring Boot instead of Spring Framework, feel free to close this issue.

[bclozel]

Before moving this issue to Spring Boot, I’d like to ensure that using other dispatcher types (error or include) would work as expected with the filter. The filter is a « once per request filter » now and I’m not sure this fits here.

[wapkch]

Before moving this issue to Spring Boot, I’d like to ensure that using other dispatcher types (error or include) would work as expected with the filter. The filter is a « once per request filter » now and I’m not sure this fits here.

You're right, using other dispatcher types still don't work cause it's a OncePerRequestFilter now. But add a tomcat TraceValve(Like Spring Cloud Sleuth instrument does) will make it work:

public class TraceValve extends ValveBase {

	private final ObservationRegistry observationRegistry;

	public TraceValve(ObservationRegistry observationRegistry) {
		this.observationRegistry = observationRegistry;
	}

	@Override
	public void invoke(Request request, Response response) throws IOException, ServletException {
		Observation observation = Observation
				.createNotStarted(TraceValve.class.getName(), observationRegistry).start();
		try (Observation.Scope scope = observation.openScope()) {
			Valve next = getNext();
			if (null == next) {
				// no next valve
				return;
			}
			next.invoke(request, response);
		} catch (Exception exception) {
			observation.error(exception);
			throw exception;
		} finally {
			// Only stop Observation if async processing is done or has never been started.
			if (!request.isAsyncStarted()) {
				Throwable error = (Throwable) request.getAttribute(RequestDispatcher.ERROR_EXCEPTION);
				if (error != null) {
					observation.error(error);
				}
				observation.stop();
			}
		}
	}

}

I plan to add this to my project, but i'm not sure whether this should be added to apache tomcat.

[bclozel]

The Observation Servlet Filter is quite similar to what was done in Spring Boot 2.x with Metrics. I don't see a way to map it to other dispatch types without running into issues: recording the same observation multiple times, leaving observations opened, etc.

Implementing a Tomcat Valve is not acceptable from a Spring Framework perspective, as we operate at the Servlet level for MVC applications. We would have to do the same for all containers and all supported versions. I'm closing this issue as a duplicate of #29398.

[kilonet]

@wapkch how did you solve this problem in the end?

[wapkch]

@wapkch how did you solve this problem in the end?
We just added a customized tomcat ObservationValve and it worked.