Spring What happens if openScope after observation stopped? (Missing log correlation for filter errors)

Affects: 6.0.9

Using SpringBoot 3.1.0, miss log correlation when handling customized exceptions thrown by customized ErrorController. What happens if openScope after observation stopped?

Question submitted on Stack Overflow.

---

// Throw Exception in filter

public class MyFilter extends GenericFilterBean {
    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
      // ...
      throw new IllegalArgumentException("IllegalArgumentException");
    }
}

// Customized ErrorController

public class MyErrorController extends AbstractErrorController {
    @RequestMapping
    public ResponseEntity<Map<String, Object>> handler(HttpServletRequest request) {
        // ...
        Object ex = request.getAttribute(RequestDispatcher.ERROR_EXCEPTION);
        throw new MyErrorControllerException("requestInfo", (Throwable) ex, status); 
    }
}

// Customized ExceptionHandler

@ExceptionHandler(Throwable.class)
public ResponseEntity<MessageSourceResult> handler(Throwable ex, HttpServletRequest request, HttpServletResponse response) {
    Observation observation = (Observation) request.getAttribute(ServerHttpObservationFilter.class.getName() + ".observation");
    if (null != observation) {

**        // If I want to get the traceId here, what should I do? Is the following code correct? **
        try (Observation.Scope scope = observation.openScope()) {
            response.setHeader("X-B3-TraceId", tracer.currentTraceContext().context().traceId());
            log.warn("Missing log correlation...");
            // ...
        }
    }

}

ServerHttpObservationFilter invoked observation.stop() in the finally block // org.springframework.web.filter.ServerHttpObservationFilter

protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
    Observation observation = createOrFetchObservation(request, response);
    try (Observation.Scope scope = observation.openScope()) {
        filterChain.doFilter(request, response);
    } catch (Exception ex) {
        observation.error(unwrapServletException(ex));
        response.setStatus(HttpStatus.INTERNAL_SERVER_ERROR.value());
        throw ex;
    } finally {
      // Only stop Observation if async processing is done or has never been started.
        if (!request.isAsyncStarted()) {
            Throwable error = fetchException(request);
            if (error != null) {
                observation.error(error);
            }
            observation.stop();
        }
    }
}

Sample: https://github.com/PerryZhao/spring-filter-error-lost-log-correlation-demo/tree/main 1. Start the application 2. Access http:localhost:8080/api/demo three times The output log is as follows:

2023-06-20T10:54:52.062+08:00  INFO [,649114fc015265da50f38998b7df244d,50f38998b7df244d] 70495 --- [nio-8080-exec-1] org.example.filter.MyTestFilter          : My filter
2023-06-20T10:54:52.077+08:00 DEBUG [,,] 70495 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error", parameters={}
2023-06-20T10:54:52.097+08:00  WARN [,,] 70495 --- [nio-8080-exec-1] o.example.exception.MyExceptionHandler   : Exception occurred.
2023-06-20T10:54:52.097+08:00  WARN [,649114fc015265da50f38998b7df244d,50f38998b7df244d] 70495 --- [nio-8080-exec-1] o.example.exception.MyExceptionHandler   : Scoped.
2023-06-20T10:54:52.114+08:00 DEBUG [,,] 70495 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 400
2023-06-20T10:55:05.816+08:00  INFO [,649115091a05da24cbd6ec5bcfb4e1f5,cbd6ec5bcfb4e1f5] 70495 --- [nio-8080-exec-2] org.example.filter.MyTestFilter          : My filter
2023-06-20T10:55:05.817+08:00 DEBUG [,,] 70495 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error", parameters={}
2023-06-20T10:55:05.818+08:00  WARN [,,] 70495 --- [nio-8080-exec-2] o.example.exception.MyExceptionHandler   : Exception occurred.
2023-06-20T10:55:05.820+08:00 DEBUG [,,] 70495 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 400
2023-06-20T10:55:16.913+08:00  INFO [,64911514535e0aa94e10eb69074d6a82,4e10eb69074d6a82] 70495 --- [nio-8080-exec-3] org.example.filter.MyTestFilter          : My filter
2023-06-20T10:55:16.914+08:00 DEBUG [,,] 70495 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error", parameters={}
2023-06-20T10:55:16.915+08:00  WARN [,,] 70495 --- [nio-8080-exec-3] o.example.exception.MyExceptionHandler   : Exception occurred.
2023-06-20T10:55:16.915+08:00  WARN [,64911514535e0aa94e10eb69074d6a82,4e10eb69074d6a82] 70495 --- [nio-8080-exec-3] o.example.exception.MyExceptionHandler   : Scoped.
2023-06-20T10:55:16.916+08:00 DEBUG [,,] 70495 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 400

Comment From: bclozel

Closing in favor of the StackOverflow question.