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
- Start the application
- 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
Comment From: 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.
Comment From: 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
Comment From: 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.
Comment From: 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.
Comment From: 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.
Comment From: 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.
Comment From: kilonet
@wapkch how did you solve this problem in the end?
Comment From: wapkch
@wapkch how did you solve this problem in the end? We just added a customized tomcat
ObservationValveand it worked.