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

huangapple go评论57阅读模式
英文:

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

问题

background:
SpringBoot 3.1.0 - 内嵌Tomcat
示例:https://github.com/PerryZhao/spring-filter-error-lost-log-correlation-demo/tree/main

// 在过滤器中抛出异常

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

// 自定义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); 
    }
}

// 自定义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) {

**        // 如果我想在这里获取traceId,应该怎么做?下面的代码是否正确?
**
        try (Observation.Scope scope = observation.openScope()) {
            response.setHeader("X-B3-TraceId", tracer.currentTraceContext().context().traceId());
            log.warn("Missing log correlation...");
            // ...
        }
    }
    
}

ServerHttpObservationFilter在finally块中调用observation.stop()

// 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 {
      // 仅在异步处理完成或从未启动时停止Observation。
        if (!request.isAsyncStarted()) {
            Throwable error = fetchException(request);
            if (error != null) {
                observation.error(error);
            }
            observation.stop();
        }
    }
}

Q: 如果在observation停止后调用openScope会发生什么?

英文:

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(&quot;IllegalArgumentException&quot;);
    }
}

// Customized ErrorController

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

// Customized ExceptionHandler

@ExceptionHandler(Throwable.class)
public ResponseEntity&lt;MessageSourceResult&gt; handler(Throwable ex, HttpServletRequest request, HttpServletResponse response) {
    Observation observation = (Observation) request.getAttribute(ServerHttpObservationFilter.class.getName() + &quot;.observation&quot;);
    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(&quot;X-B3-TraceId&quot;, tracer.currentTraceContext().context().traceId());
            log.warn(&quot;Missing log correlation...&quot;);
            // ...
        }
    }
    
}

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?

答案1

得分: 1

整个Spring MVC中的请求处理都发生在由ServerHttpObservationFilter打开的范围内。无需打开新范围,因为当前观察已经在范围内。从跟踪器中获取traceId应该足够。

编辑:
在审查示例应用程序后,我现在明白了这里的行为。您的自定义过滤器MyFilter引发了异常,此异常上升到ServerHttpObservationFilter,后者关闭了当前观察和范围。然后,Servlet容器为同一请求触发ERROR分派,并且处理此错误。由于ServerHttpObservationFilter是一个OncePerRequestFilter,因此我们不会为此请求启动另一个观察(我认为该过滤器仅映射到请求和异步分派类型)。由于观察已关闭,日志中缺少traceId。创建新的观察不会显示正确的关联ID。

我不确定如何在不创建重复观察或记录错误信息的情况下改进情况。请随时为此创建一个Spring Framework问题

英文:

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.

huangapple
  • 本文由 发表于 2023年6月16日 14:43:06
  • 转载请务必保留本文链接:https://go.coder-hub.com/76487558.html
匿名

发表评论

匿名网友

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen:

确定