0

background: SpringBoot 3.1.0 - embedded tomcat
Sample: https://github.com/PerryZhao/spring-filter-error-lost-log-correlation-demo/tree/main

// 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();
        }
    }
}

Q: What happens if openScope after observation stopped?

Perry Zhao
  • 68
  • 4

1 Answers1

1

The entire request handling in Spring MVC happens within the scope that is opened by the ServerHttpObservationFilter. There is no need to open a new scope, as the current observation is already in scope. Getting the traceId from the tracer should be enough.

Edit: After reviewing the sample application I understand now the behavior here. Your custom filter MyFilter is throwing an exception, this exception bubbles up to the ServerHttpObservationFilter which closes the current observation and scope. The Servlet container then triggers an ERROR dispatch for this same request and this error is handled. Since the ServerHttpObservationFilter is a OncePerRequestFilter, we do not start another observation for this request (and I believe the filter is only mapped to request and async dispatch types). The traceId are missing from the logs since the observation is closed. Creating a new one would not show the right correlation id here.

I'm not sure how to improve the situation without creating a duplicate observation or record the wrong information. Feel free to create a Spring Framework issue for that.

Brian Clozel
  • 56,583
  • 15
  • 167
  • 176
  • Thank you for your reply. If the exception is occurred in the Controller, the TraceId can be obtained directly in the ExceptionHandler, but in the Catch block of ServerHttpObservationFilter, the scope has been closed by try with resource, so after sendError, the exception handled by ExceptionHandler which thrown in the ErrorController will missing log correlation. Code Sample: https://github.com/PerryZhao/spring-filter-error-lost-log-correlation-demo/tree/main – Perry Zhao Jun 21 '23 at 10:54
  • missing from which log? – Brian Clozel Jun 22 '23 at 09:43
  • Sorry about my text format.. **Missing traceId at `Exception occurred`** [Sample ExceptionHandler](https://github.com/PerryZhao/spring-filter-error-lost-log-correlation-demo/blob/main/src/main/java/org/example/exception/MyExceptionHandler.java) The output log is as follows: ~~~ 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.915+08:00 WARN [,,] 70495 --- [nio-8080-exec-3] o.example.exception.MyExceptionHandler : Exception occurred. ~~~ – Perry Zhao Jun 25 '23 at 07:46
  • edited my answer – Brian Clozel Jun 26 '23 at 07:53
  • Thank you for your reply. I come to realize the truth until I saw "(and I believe the filter is only mapped to request and async dispatch types)". Compared with spring-cloud-sleuth, we temporarily register our own webMvcObservationFilter to solve this problem. Thanks again for your patient reply. – Perry Zhao Jun 27 '23 at 02:48