记录线上参数丢失的排查过程。

一, 问题描述：

在线上服务, 偶尔会收到巡检报警, 提示{"msg":"应用ID不能为空","code":10001, "traceId":"xxxxxxxxxxx"}.

此异常是在通用模块中抛出, 是因为没有获取到app_id

com.xxxx.exception.BizException: 应用ID不能为空
    at com.xxxx.paas.platform.authentication.intercepter.APICommonParam$APIParamChecker.checkAppId(APICommonParam.java:32)
    at com.xxxx.paas.platform.authentication.intercepter.APIInterceptor.checkCommonParams(APIInterceptor.java:35)
    at com.xxxx.paas.platform.authentication.intercepter.AbstractInterceptor.preHandle(AbstractInterceptor.java:77)

代码:

RequestLogFilter 主要用来记录每次请求日志.

public class RequestLogFilter extends OncePerRequestFilter {
    private static final Logger log = LoggerFactory.getLogger(RequestLogFilter.class);

    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain chain) throws ServletException, IOException {
        Date beginTime = new Date();
        Map<String, String> query = ServletUtil.getParamMap(request);
                chain.doFilter(request, response);
                log.info("query: {}", query);
                .... 
}

AbstractInterceptor 用来做通用参数校验.

public abstract class AbstractInterceptor implements HandlerInterceptor {
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {

        Map<String, String> query = ServletUtil.getParamMap(request);
        String appId = query.get("appId");
        if(appId == null || appId.length() == 0){
                throw new BizException(10001, "appId 不能为空!");
        }
        .... 
        return true;
    }
}

经过查看日志发现, 请求中的参数完全丢失. 出现的次数毫无规律.

二, 有可能出现问题的点

最初怀疑是以下几种可能导致:

  1. 网络链路比较复杂, 是不是网关服务(APISIX或Nginx)导致参数没有转发到应用程序, 而应用程序根本没有收到请求参.

  2. 自定义Filter, 导致参数在Filter中丢失

  3. Tomcat 中可以设置PostSize, PostSize 计算错误导致

    在Tomcat中, request.getParameters() 方法获取参数时, 有这么一段逻辑, 当contentLength 大于maxPostSize时, 会忽略参数解析. 如果忽略掉参数会打印如下日志:

    Parameters were not parsed because the size of the posted data was too big. Use the maxPostSize attribute of the connector to resolve this if the application should accept large POSTs.

    具体代码如下:

     // org.apache.catalina.connector.Request
 /**
  * Parse request parameters.
  */
 protected void parseParameters() {
     **parametersParsed = true;**

     Parameters parameters = coyoteRequest.getParameters();
     boolean success = false;
     try {
         .....

         int len = getContentLength();

         if (len > 0) {
                         // 获取maxPostSize
             int maxPostSize = connector.getMaxPostSize();
             // 比较
                         if ((maxPostSize >= 0) && (len > maxPostSize)) {
                 Context context = getContext();
                 if (context != null && context.getLogger().isDebugEnabled()) {
                     // 打印日志
                                         **context.getLogger().debug(
                             sm.getString("coyoteRequest.postTooLarge"));**
                 }
                 checkSwallowInput();
                 parameters.setParseFailedReason(FailReason.POST_TOO_LARGE);
                 return;
             }

         } else if ("chunked".equalsIgnoreCase(
                 coyoteRequest.getHeader("transfer-encoding"))) {
            .....
         }
         success = true;
     } finally {
         if (!success) {
             parameters.setParseFailedReason(FailReason.UNKNOWN);
         }
     }

 }

三, 验证

1. Java程序根本没有收到请求参数

为了验证这个问题, 特意让运维同志帮忙在服务器中一下包.

kubectl exec prod-paas-xxxxxxxx-xxx tcpflow -cp -i any port 8080 >> /root/xxxx.log -n prod-paas

抓包后发现 数据包中带有请求参数, 

192.168.066.xxx.18860-192.168.xxx.xxx.08080: POST /api/v2/xxxx/xxxx HTTP/1.1
Host: api.xxx.com
X-Real-IP: 101.200.xxx.xxx
X-Forwarded-For: 101.200.xx.xxx
X-Forwarded-Proto: https
X-Forwarded-Host: xxxxxx
X-Forwarded-Port: 9443
Content-Length: 85
User-Agent: python-requests/2.24.0
Accept-Encoding: gzip, deflate
Accept: */*
Content-Type: application/x-www-form-urlencoded
X-Real-SCHEME: https

**app_id=xxx&signed_at=xxxx&sign=xxx**
192.168.161.xxx.08080-192.168.066.xxx.18860: HTTP/1.1 200 
Vary: Origin
Vary: Access-Control-Request-Method
Vary: Access-Control-Request-Headers
Content-Type: application/json
Transfer-Encoding: chunked
Date: Wed, 13 Apr 2022 16:40:05 GMT

65
{"code":10001,"msg":"ID","data":null,"trace_id":"e1051006938d4f00bc7791e945d48e6e"}

ES 日志: 

{
    "method": "POST",
    "url": "/api/v2/xxx/xxxx",
    "urlMatch": "/api/v2/xxx/xxxxx",
    "args": {
        **"query": {},**
        "header": {
            "x-real-ip": "101.200.40.xxx",
            "content-type": "application/x-www-form-urlencoded",
            "user-agent": "python-requests/2.24.0",
            "content-lenght":85,
            }
    },
    "result": {
        "msg": "应用ID不能为空",
        "code": 10001
    },
    "begin": "2022-04-14 00:40:05",
    "ends": "2022-04-14 00:40:05",
    "duration": 1,
    "utype": 0,
    "clientIP": "101.200.40.xxx"
}

然而, 在程序中还是出现了参数丢失的现象, 所有排除了这种可能性

2. 在Filter将request传入至其他线程导致参数丢失。

检查所有注册的Filter 后, 发现在RequestLogFilter 之前注册的filter 均没有修改Request的操作, 所有也可以排除这种可能性.

Untitled

3. 请求参数长度超过PostSize

为了验证是不是这个问题导致 需要修改tomcat 日志级别, 在启动参数添加如下命令:

--logging.level.org.apache.catalina=DEBUG \

--logging.level.org.apache.tomcat.util.http=DEBUG \

--logging.level.org.apache.catalina.session.ManagerBase=INFO \

--loging.level.org.apache.catalina.loader.WebappClassLoaderBase=INFO

调整日志级别, 复现问题后, 日志如下:

Apr 20, 2022 @ 14:25:39.179 |    com.xxxx.web.filter.RequestLogFilter |    INFO |    {"method":"POST","url":"/api/v2/xxxx/xxxx","urlMatch":"/api/v2/xxxx/xxxx","args":{"query":{},"header":{"content-type":"application/x-www-form-urlencoded","user-agent":"python-requests/2.26.0"}},"result":{"msg":"应用ID不能为空","code":10001},"begin":"2022-04-20 14:25:39","ends":"2022-04-20 14:25:39","duration":1,"utype":0,"clientIP":"192.168.13.1"} |    1871d421a44c402ba0c4bda39ccdd4fc |    http-nio-8080-exec-8

Apr 20, 2022 @ 14:25:39.178    | org.apache.catalina.valves.RemoteIpValve |    DEBUG |    Incoming request /api/v2/xxxx/xxxx with originalRemoteAddr [192.168.13.1], originalRemoteHost=[192.168.13.1], originalSecure=[false], originalScheme=[http], originalServerName=[xxxx.xxxx.domain], originalServerPort=[80] will be seen as newRemoteAddr=[192.168.13.1], newRemoteHost=[192.168.13.1], newSecure=[false], newScheme=[http], newServerName=[xxxx.xxxx.domain], newServerPort=[80] |    -  |    http-nio-8080-exec-8

Apr 20, 2022 @ 14:25:39.178    | com.xxxx.web.handler.GlobalExceptionHandler |    WARN |    [xxxx-web] [handleBizException] |    1871d421a44c402ba0c4bda39ccdd4fc    http-nio-8080-exec-8

Apr 20, 2022 @ 14:25:39.178    | org.apache.catalina.authenticator.AuthenticatorBase |    DEBUG |    Security checking request POST /api/v2/xxxx/xxxx     |    -  |    http-nio-8080-exec-8

Apr 20, 2022 @ 14:25:39.178    | org.apache.catalina.realm.RealmBase |    DEBUG |    No applicable constraints defined     |    -  |    http-nio-8080-exec-8

Apr 20, 2022 @ 14:25:39.178    | org.apache.catalina.authenticator.AuthenticatorBase |    DEBUG |    Not subject to any constraint |    -  | http-nio-8080-exec-8

通过分析日志后发现 ,程序根本没有执行到这个方法, 也没有打印相应的日志信息. 所以也排除这种可能性.

四, 深入排查

还是没有找到问题后, 只能继续在Tomcat 中添加日志. 打印进入每一个Filter的Request, 在ApplicationFilterChain增加以下日志:

// org.apache.catalina.core.ApplicationFilterChain
private void internalDoFilter(ServletRequest request, ServletResponse response) throws IOException, ServletException {

    ......
        if (pos < n) {
        ApplicationFilterConfig filterConfig = filters[pos++];
        try {
            Filter filter = filterConfig.getFilter();
                        // **加入日志, 打印Filter 信息 1**
                        **log.info("current filter: {}, request: {}. response: {}", filter.getClass(), request.getClass(), response.getClass());**
            if (request.isAsyncSupported() && "false".equalsIgnoreCase(
                    filterConfig.getFilterDef().getAsyncSupported())) {
                request.setAttribute(Globals.ASYNC_SUPPORTED_ATTR, Boolean.FALSE);
            }
            if( Globals.IS_SECURITY_ENABLED ) {
                final ServletRequest req = request;
                final ServletResponse res = response;
                Principal principal =
                    ((HttpServletRequest) req).getUserPrincipal();

                Object[] args = new Object[]{req, res, this};
                SecurityUtil.doAsPrivilege ("doFilter", filter, classType, args, principal);
            } else {
                filter.doFilter(request, response, this);
            }
        } catch (IOException | ServletException | RuntimeException e) {
            throw e;
        } catch (Throwable e) {
            e = ExceptionUtils.unwrapInvocationTargetException(e);
            ExceptionUtils.handleThrowable(e);
            throw new ServletException(sm.getString("filterChain.filter"), e);
        }
        return;
    }

   ......
}

然后复现问题后, 日志如下:

Apr 22, 2022 @ 14:37:30.550|com.xxxx.web.filter.RequestLogFilter|INFO|{"method":"POST","url":"/api/v2/xxxx/xxxx","urlMatch":"/api/v2/xxxx/xxxx","args":{"query":{},"header":{"content-length":"141","content-type":"application/x-www-form-urlencoded","user-agent":"python-requests/2.26.0"}},"result":{"msg":"应用ID不能为空","code":10001},"begin":"2022-04-22 14:37:30","ends":"2022-04-22 14:37:30","duration":1,"utype":0,"clientIP":"192.168.13.1"}|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class com.xxxx.web.filter.TenantFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class com.xxxx.web.filter.RequestLogFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class org.springframework.boot.web.servlet.filter.OrderedFormContentFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.authenticator.AuthenticatorBase|DEBUG|Security checking request POST /api/v2/xxxx/xxxx| - 

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.valves.RemoteIpValve|DEBUG|Incoming request /api/v2/xxxx/xxxx with originalRemoteAddr [192.168.13.1], originalRemoteHost=[192.168.13.1], originalSecure=[false], originalScheme=[http], originalServerName=[xxxx.xxxxx.domain], originalServerPort=[80] will be seen as newRemoteAddr=[192.168.13.1], newRemoteHost=[192.168.13.1], newSecure=[false], newScheme=[http], newServerName=[xxxx.xxxx.domain], newServerPort=[80]| - 

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class org.springframework.boot.web.servlet.filter.OrderedRequestContextFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class org.springframework.boot.web.servlet.filter.OrderedCharacterEncodingFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade| - 

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade| - 

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.authenticator.AuthenticatorBase|DEBUG|Not subject to any constraint| - 

Apr 22, 2022 @ 14:37:30.549|com.xxxx.web.handler.GlobalExceptionHandler|WARN|[xxxx-web] [handleBizException]|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class com.xxxx.paas.xxxx.lss.manager.filter.MediaTypeFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class org.springframework.web.filter.CorsFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade| - 

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class com.xxxx.log.trace.WebTraceFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade| - 

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class org.apache.tomcat.websocket.server.WsFilter, request: class com.xxxx.paas.xxxx.lss.manager.filter.MediaTypeFilter$1 ,response: class org.apache.catalina.connector.ResponseFacade|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.realm.RealmBase|DEBUG|  No applicable constraints defined| - 

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class com.xxxx.web.filter.RequestCacheFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade|4850227c8ae4442bbcd187c52147a8d2

Apr 22, 2022 @ 14:37:30.549|org.apache.catalina.core.ApplicationFilterChain|INFO|current filter: class com.xxxx.web.filter.XssFilter, request: class org.apache.catalina.connector.RequestFacade ,response: class org.apache.catalina.connector.ResponseFacade|4850227c8ae4442bbcd187c52147a8d2

分析后发现, Request 均正常. 所以排除这种可能性.

没有办法, 只能进一步阅读Tomcat 源码, 查看了一下request.getParameterMap()具体的流程, 发现两个比较核心的变量:

  1. 在Request 类中有个变量 parametersParsed 来标识参数是否解析完成.
  2. 在ParameterMap中有一个locked 变量, 来标识参数是否已锁定.

具体代码如下:

// org.apache.catalina.connector.Request
@Override
public Map<String, String[]> getParameterMap() {
        // 判断参数是否已经被锁定
    if (**parameterMap.isLocked()**) {
                **log.info("isLocked");** // 1
        return parameterMap;
    }
        // 获取参数
    Enumeration<String> enumeration = getParameterNames();
    while (enumeration.hasMoreElements()) {
        String name = enumeration.nextElement();
        String[] values = getParameterValues(name);
        parameterMap.put(name, values);
    }
        // 锁定
    **parameterMap.setLocked(true);**

    return parameterMap;

}

@Override
public Enumeration<String> getParameterNames() {
  log.info("getParameterNames"); // 2
  // 判断参数是否已经解析
    if (!**parametersParsed**) {
     // 参数解析(具体的解析操作)
            **log.info("parametersParsed is false");** // 3
            parseParameters();
  }
    return coyoteRequest.getParameters().getParameterNames();

}

protected void parseParameters() {
    **log.info("parseParameters");** // 4
        // 已解析
        **parametersParsed** = true;
        ..... 解析参数
}

/**
* 释放*/
 public void recycle() {
    // 重置
    **parametersParsed** = false;
    // org.apache.catalina.connector.RECYCLE_FACADES
    if (getDiscardFacades()) {
        parameterMap = new ParameterMap<>();
    } else {
        // 重置
                **parameterMap.setLocked(false);**
        **parameterMap.clear();**
    }

    .....
}

// org.apache.catalina.core.ApplicationFilterChain
private void internalDoFilter(ServletRequest request, ServletResponse response)
    throws IOException, ServletException {

    // Call the next filter if there is one
    if (pos < n) {
        ApplicationFilterConfig filterConfig = filters[pos++];
        try {
            Filter filter = filterConfig.getFilter();
            **if(request instanceof RequestFacade){
                RequestFacade req = (RequestFacade) request;
                Request request1 = req.getRequest();
                if(request1 != null){
                    logger.info("request1: {}, hash: {}", request1.getClass(), System.identityHashCode(this));
                }
            }**
            .....
    }

Untitled

通过阅读源码发现, 没有调用parseParameters() 方法只有两种可能:

  1. parameterMap.isLocked() 方法返回true
  2. parametersParsed 为true

于是加日志后继续复现问题, 问题复现后, 日志如下:

Apr 24, 2022 @ 11:31:58.009|org.apache.catalina.core.ApplicationFilterChain|INFO|request1: class org.apache.catalina.connector.Request, hash: 633159667|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.009|org.apache.catalina.core.ApplicationFilterChain|INFO|request1: class org.apache.catalina.connector.Request, hash: 633159667|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.009|org.apache.catalina.core.ApplicationFilterChain|INFO|request1: class org.apache.catalina.connector.Request, hash: 633159667|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.009|org.apache.catalina.core.ApplicationFilterChain|INFO|request1: class org.apache.catalina.connector.Request, hash: 633159667|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.009|org.apache.catalina.core.ApplicationFilterChain|INFO|request1: class org.apache.catalina.connector.Request, hash: 633159667|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.009|org.apache.catalina.connector.Request|INFO|**getParameterNames**|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.009|org.apache.catalina.connector.Request|INFO|**isLocked**|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.009|com.xxxx.web.filter.RequestLogFilter|INFO|{"method":"POST","url":"/api/v2/xxxx/xxxx","urlMatch":"/api/v2/room/xxxx","args":{"query":{},"header":{"content-length":"141","content-type":"application/x-www-form-urlencoded","user-agent":"python-requests/2.26.0"}},"result":{"msg":"应用ID不能为空","code":10001},"begin":"2022-04-24 11:31:58","ends":"2022-04-24 11:31:58","duration":0,"utype":0,"clientIP":"192.168.13.1"}|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.009|com.xxxx.web.handler.GlobalExceptionHandler|WARN|[xxxx-web] [handleBizException]|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.008|org.apache.catalina.core.ApplicationFilterChain|INFO|request1: class org.apache.catalina.connector.Request, hash: 633159667|a7e72914e9c94b39ab3e1db3225e7b10

Apr 24, 2022 @ 11:31:58.008|org.apache.catalina.core.ApplicationFilterChain|INFO|request1: class org.apache.catalina.connector.Request, hash: 633159667|a7e72914e9c94b39ab3e1db3225e7b10

由此, 可以断定, 是因为parametersParsed 参数导致.

那么问题又来了, 什么情况会导致这个问题?

  1. HttpServletRequest 对象传入其他线程, 被多个线程操作, 导致该问题.(不同线程调用request.getParameterMap())
    1. @Async
    2. parallelStream
    3. ThreadPool
    4. CompletableFuture

五, 发现问题

现在可以确定的是Request对象使用不当导致, 带着这个问题, 检查项目中所有代码后, 共有三个地方调用了request.getParameterMap() , 分别是RequestLogFilter, AbstractInterceptor和FilledValidator.

发现FilledValidato中会将当前线程的 Request对象保存到成员变量里, 这就导致一个问题, 当某个线程第一次执行initialize的时候保存的是 Reqeust@1234. 后续无论哪个线程调用isValid 时, 使用的都是Reqeust@1234.

具体代码如下:

/**
 * 自定义注解, 实现Filled 校验
 */
@Slf4j
public class FilledValidator implements ConstraintValidator<Filled, Object> {
    HttpServletRequest request;
    Filled annotation;

    // 此方法只会初始化一次
        @Override
    public void initialize(Filled annotation) {
        ConstraintValidator.super.initialize(annotation);
        this.annotation = annotation;
        // 问题所在
                **this.request = ((ServletRequestAttributes) (RequestContextHolder.currentRequestAttributes())).getRequest();**
                log.info("FilledValidator#initialize, request: {}", this.request); // 1
    }

    @Override
    public boolean isValid(Object value, ConstraintValidatorContext context) {
                log.info("FilledValidator#isValid, request: {}", this.request);  // 2      
                // 字段名称
        String fieldName = annotation.value();
        // 检查请求参数中是否存在改字段
        if (RequestUtils.checkParamIsExist(request, fieldName) && isNullOrEmpty(value)) {
            throw new BizException(annotation.errorCode(), annotation.message());
        }
        return true;
    }

    private boolean isNullOrEmpty(Object data) {
           ...
           return true;
    }
}

/**
 * 检查参数是否存在
 *
 * @param request
 * @param fieldName
 * @return
 */
// RequestUtils.java
public static boolean checkParamIsExist(HttpServletRequest request, String fieldName) {
    log.info("RequestUtils#checkParamIsExist, request: {}, field: {}", request, fieldName); // 3
    if (request != null && fieldName != null) {
        Enumeration<String> parameterNames = request.getParameterNames();
        while (parameterNames.hasMoreElements()) {
            String nextElement = parameterNames.nextElement();
            if (nextElement.equals(fieldName)) {
                return true;
            }
        }
    }
    return false;
}
/**
 * Filled 校验.
 * <p>
 * 当请求参数中存在某个字段时, 该值不能为空. 如果请求参数中不存在该字段, 则忽略此校验.
 */
@Target({ElementType.PARAMETER, ElementType.FIELD})
@Retention(RetentionPolicy.RUNTIME)
@Constraint(validatedBy = {FilledValidator.class})
@Documented
@Repeatable(Filled.List.class)
public @interface Filled {
    String value();

    String message() default "网络异常，请联系管理员";

    int errorCode() default 500;

    /**
     * 分组
     *
     * @return
     */
    Class<?>[] groups() default {};

    Class<? extends Payload>[] payload() default {};

    @Target({FIELD, PARAMETER})
    @Retention(RUNTIME)
    @Documented
    @interface List {
        Filled[] value();
    }
}

加上日志后继续复现问题, 日志如下:

2022-04-28 15:55:43.048 [http-nio-8888-exec-2] [] INFO  org.apache.catalina.connector.CoyoteAdapter - service..., this: org.apache.catalina.connector.CoyoteAdapter@675ceaf2
2022-04-28 15:55:43.065 [http-nio-8888-exec-2] [] INFO  org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/] - Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-04-28 15:55:43.066 [http-nio-8888-exec-2] [] INFO  org.springframework.web.servlet.DispatcherServlet - Initializing Servlet 'dispatcherServlet'
2022-04-28 15:55:43.068 [http-nio-8888-exec-2] [] INFO  org.springframework.web.servlet.DispatcherServlet - Completed initialization in 2 ms
2022-04-28 15:55:43.074 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  org.apache.catalina.core.ApplicationFilterChain - current filter: com.itrjp.demo.filter.RequestLogFilter@5d1e0fbb, request: org.apache.catalina.connector.RequestFacade@39a211de, response: org.apache.catalina.connector.RequestFacade@39a211de
2022-04-28 15:55:43.077 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  org.apache.catalina.connector.Request - getParameterNames, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 15:55:43.077 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  org.apache.catalina.connector.Request - parametersParsed is false, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 15:55:43.077 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  org.apache.catalina.connector.Request - **parseParameters, this: org.apache.catalina.connector.Request@6225cd9d**
2022-04-28 15:55:43.078 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParams, request: org.apache.catalina.connector.RequestFacade@39a211de, params: org.apache.catalina.util.ParameterMap@3b19fef6
2022-04-28 15:55:43.078 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParamMap, request: org.apache.catalina.connector.RequestFacade@39a211de, params: {pos=1, appId=d317f559, signed_at=1650524409, limit=10, sign=vhall}
2022-04-28 15:55:43.085 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.interceptor.ParamCheckInterceptor - ParamCheckInterceptor#preHandle, request: org.apache.catalina.connector.RequestFacade@39a211de, response: org.springframework.web.util.ContentCachingResponseWrapper@31f6b7e2
2022-04-28 15:55:43.086 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  org.apache.catalina.connector.Request - isLocked, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 15:55:43.086 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParams, request: org.apache.catalina.connector.RequestFacade@39a211de, params: org.apache.catalina.util.ParameterMap@3b19fef6
2022-04-28 15:55:43.086 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParamMap, request: org.apache.catalina.connector.RequestFacade@39a211de, params: {pos=1, appId=d317f559, signed_at=1650524409, limit=10, sign=vhall}
2022-04-28 15:55:43.159 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  org.apache.catalina.connector.Request - getParameterNames, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 15:55:43.205 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.valid.FilledValidator - **FilledValidator#initialize**, request: org.apache.catalina.connector.**RequestFacade@39a211de**
2022-04-28 15:55:43.206 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.valid.FilledValidator - **FilledValidator#isValid**, request: org.apache.catalina.connector.RequestFacade@39a211de
2022-04-28 15:55:43.206 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#checkParamIsExist, request: org.apache.catalina.connector.RequestFacade@39a211de, field: userName
2022-04-28 15:55:43.206 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  org.apache.catalina.connector.Request - getParameterNames, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 15:55:43.208 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.controller.UserController - UserController#update, param: UserUpdateParam(userId=null, userName=null)
2022-04-28 15:55:43.252 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  com.itrjp.demo.filter.RequestLogFilter - url: http://localhost:8888/api/user/update, method: POST, queryStr: null, param: {pos=1, appId=d317f559, signed_at=1650524409, limit=10, sign=vhall}, response statusCode: 200,  result: {"code":200,"msg":"ok","body":"ok","requestId":"5f766a39dcf046d1a8bce34478ef31e8"}, duration: 176
2022-04-28 15:55:43.255 [http-nio-8888-exec-2] [5f766a39dcf046d1a8bce34478ef31e8] INFO  org.apache.catalina.connector.Request - **recycle, this: org.apache.catalina.connector.Request@6225cd9d**

2022-04-28 16:11:34.839 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.core.ApplicationFilterChain - current filter: com.itrjp.demo.filter.RequestLogFilter@5d1e0fbb, request: org.apache.catalina.connector.RequestFacade@2e678e97, response: org.apache.catalina.connector.RequestFacade@2e678e97
2022-04-28 16:11:34.839 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - getParameterNames, this: org.apache.catalina.connector.Request@48464682
2022-04-28 16:11:34.839 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - parametersParsed is false, this: org.apache.catalina.connector.Request@48464682
2022-04-28 16:11:34.839 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - parseParameters, this: org.apache.catalina.connector.Request@48464682
2022-04-28 16:11:34.839 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParams, request: org.apache.catalina.connector.RequestFacade@2e678e97, params: org.apache.catalina.util.ParameterMap@6c3a8a63
2022-04-28 16:11:34.840 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParamMap, request: org.apache.catalina.connector.RequestFacade@2e678e97, params: {appId=xxxxxxx}
2022-04-28 16:11:34.840 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.interceptor.ParamCheckInterceptor - ParamCheckInterceptor#preHandle, request: org.apache.catalina.connector.RequestFacade@2e678e97, response: org.springframework.web.util.ContentCachingResponseWrapper@1a1b41d0
2022-04-28 16:11:34.840 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - isLocked, this: org.apache.catalina.connector.Request@48464682
2022-04-28 16:11:34.840 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParams, request: org.apache.catalina.connector.RequestFacade@2e678e97, params: org.apache.catalina.util.ParameterMap@6c3a8a63
2022-04-28 16:11:34.840 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParamMap, request: org.apache.catalina.connector.RequestFacade@2e678e97, params: {appId=xxxxxxx}
2022-04-28 16:11:34.893 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - getParameterNames, this: org.apache.catalina.connector.Request@48464682
2022-04-28 16:11:34.894 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.valid.FilledValidator - **FilledValidator#isValid**, request: org.apache.catalina.connector.RequestFacade@39a211de
2022-04-28 16:11:34.894 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.util.RequestUtils - **RequestUtils#checkParamIsExist**, request: org.apache.catalina.connector.RequestFacade@39a211de, field: userName
2022-04-28 16:11:34.894 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - **getParameterNames**, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 16:11:34.894 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - **parametersParsed is false**, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 16:11:34.894 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - **parseParameters, this: org.apache.catalina.connector.Request@6225cd9d**
2022-04-28 16:11:34.895 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.controller.UserController - UserController#update, param: UserUpdateParam(userId=null, userName=null)
2022-04-28 16:11:34.895 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  com.itrjp.demo.filter.RequestLogFilter - url: http://localhost:8888/api/user/update, method: POST, queryStr: null, param: {appId=xxxxxxx}, response statusCode: 200,  result: {"code":200,"msg":"ok","body":"ok","requestId":"bee13a72ac64472888bdc1c3ec8c6ab2"}, duration: 56
2022-04-28 16:11:34.895 [http-nio-8888-exec-4] [bee13a72ac64472888bdc1c3ec8c6ab2] INFO  org.apache.catalina.connector.Request - **recycle, this: org.apache.catalina.connector.Request@48464682**

2022-04-28 16:18:32.576 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  org.apache.catalina.core.ApplicationFilterChain - current filter: com.xxxx.xxxx.filter.RequestLogFilter@5d1e0fbb, request: org.apache.catalina.connector.RequestFacade@39a211de, response: org.apache.catalina.connector.RequestFacade@39a211de
2022-04-28 16:18:32.576 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  org.apache.catalina.connector.Request - getParameterNames, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 16:18:32.576 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParams, request: org.apache.catalina.connector.RequestFacade@39a211de, params: org.apache.catalina.util.ParameterMap@3b19fef6
2022-04-28 16:18:32.577 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParamMap, request: org.apache.catalina.connector.RequestFacade@39a211de, params: {}
2022-04-28 16:18:32.577 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  org.apache.catalina.core.ApplicationFilterChain - current filter: org.apache.tomcat.websocket.server.WsFilter@a850404, request: org.apache.catalina.connector.RequestFacade@39a211de, response: org.apache.catalina.connector.RequestFacade@39a211de
2022-04-28 16:18:32.577 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  com.itrjp.demo.interceptor.ParamCheckInterceptor - ParamCheckInterceptor#preHandle, request: org.apache.catalina.connector.RequestFacade@39a211de, response: org.springframework.web.util.ContentCachingResponseWrapper@201ce457
2022-04-28 16:18:32.577 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  org.apache.catalina.connector.Request - isLocked, this: org.apache.catalina.connector.Request@6225cd9d
2022-04-28 16:18:32.577 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParams, request: org.apache.catalina.connector.RequestFacade@39a211de, params: org.apache.catalina.util.ParameterMap@3b19fef6
2022-04-28 16:18:32.577 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  com.itrjp.demo.util.RequestUtils - RequestUtils#getParamMap, request: org.apache.catalina.connector.RequestFacade@39a211de, params: {}
2022-04-28 16:18:32.583 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] ERROR com.itrjp.demo.handler.GlobalHandler - BizException, message: appId 不能为空!
2022-04-28 16:18:32.584 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  com.itrjp.demo.filter.RequestLogFilter - url: http://localhost:8888/api/user/update, method: POST, queryStr: null, param: {}, response statusCode: 400,  result: {"code":10001,"msg":"appId 不能为空!","body":null,"requestId":"56f40a5abe634d1bad5872a764a2f58e"}, duration: 8
2022-04-28 16:18:32.585 [http-nio-8888-exec-7] [56f40a5abe634d1bad5872a764a2f58e] INFO  org.apache.catalina.connector.Request - **recycle, this: org.apache.catalina.connector.Request@6225cd9d**

从以上日志可以发现, 在http-nio-8888-exec-4 线程中, FilledValidator中调用的Request对象实际上是Request@6225cd9d.

Untitled

六, 如何解决

使用Spring @Autowired自动注入Request, 而非((ServletRequestAttributes) (RequestContextHolder.*currentRequestAttributes*())).getRequest() .

@Slf4j
public class FilledValidator implements ConstraintValidator<Filled, Object> {
    **@Autowired** // +
        HttpServletRequest request;
    Filled annotation;

    // 此方法只会初始化一次
        @Override
    public void initialize(Filled annotation) {
        ConstraintValidator.super.initialize(annotation);
        this.annotation = annotation;
        // 问题所在
                // **~~this.request = ((ServletRequestAttributes) (RequestContextHolder.currentRequestAttributes())).getRequest();~~**
    }

七, 杂项

jar 包替换文件

解压:

jar xvf .\prod-paas-xxxx.jar

压缩:
jar cvf0m prod-paas-xxxx.jar META-INF/MANIFEST.MF .

Docker

  1. 加载image

    docker load < prod-paas-xxxx.tar

  2. 启动

    docker run -d -v /d/docker/prod-paas:/test -p 8080:8080 xxxxx

  3. 连接

    docker exec -it 214644b782fa /bin/bash

使用@Autowired 注入Request对象

Untitled

可以发现, 自动注入的实际上是AutowireUtils$ObjectFactoryDelegatingInvocationHandler


abstract class AutowireUtils {
        /**
         * Reflective {@linkInvocationHandler} for lazy access to the current target object.
         */
        @SuppressWarnings("serial")
        private static class ObjectFactoryDelegatingInvocationHandler implements InvocationHandler, Serializable {

           private final ObjectFactory<?> objectFactory;

           ObjectFactoryDelegatingInvocationHandler(ObjectFactory<?> objectFactory) {
              this.objectFactory = objectFactory;
           }

           @Override
           public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
              switch (method.getName()) {
                 case "equals":
                                // Only consider equal when proxies are identical.
                                return (proxy == args[0]);
                                         case "hashCode":
                                // Use hashCode of proxy.
                                return System.identityHashCode(proxy);
                 case "toString":
                    return this.objectFactory.toString();
              }
              try {
                 **return method.invoke(this.objectFactory.getObject(), args);**
              }
              catch (InvocationTargetException ex) {
                 throw ex.getTargetException();
              }
           }
        }
}

在invoke()中, 实际上调用了this.objectFactory.getObject()来获取Request对象. 然后继续查看getObject()方法

public abstract class WebApplicationContextUtils {

        private static class RequestObjectFactory implements ObjectFactory<ServletRequest>, Serializable {

                @Override
                public ServletRequest getObject() {
                    return currentRequestAttributes().getRequest();
                }

                @Override
                public String toString() {
                    return "Current HttpServletRequest";
                }
        }

        /**
         * Return the current RequestAttributes instance as ServletRequestAttributes.
         * @see RequestContextHolder#currentRequestAttributes()
         */
        private static ServletRequestAttributes currentRequestAttributes() {
                RequestAttributes requestAttr = **RequestContextHolder.currentRequestAttributes();**
                if (!(requestAttr instanceof ServletRequestAttributes)) {
                    throw new IllegalStateException("Current request is not a servlet request");
                }
                return (ServletRequestAttributes) requestAttr;
        }

}

在currentRequestAttributes() 也中调用的RequestContextHolder.currentRequestAttributes() .

Python脚本

#!/usr/bin/python
# -*- coding: UTF-8 -*-
import requests
import asyncio

async def send_post(url):
    '''
    发送请求
    :param url:
    :return:
    '''
    data = {
        "app_id": "xxxx",
        "signed_at": 1649692835,
        "room_id": "xxxxx",
        "pos": "1",
        "limit": "10",
        "start_time": "2022-04-12 01:00",
        "end_time": "2022-04-12 01:00",
        "sign": "xxxxxx"

    }
    header = {
        "content-type": "application/x-www-form-urlencoded",
        "Accept-Encoding": "gzip, deflate"
    }
    res = requests.post(url, data=data, headers=header)
    resp = res.text
    data = res.json()
    if data['code'] == 10001:
        print(data)
    return resp

async def handler(loop):
    '''

    :param loop:
    :return:
    '''
    tasks = []
    domain = "http://localhost:8888"

    url_list = [
        "/api/v2/room/get-check-pic-list",
        "/api/v2/room/set-trans-code-info",
        "/api/v2/room/describe-live-push-stream-config",
        "/api/v2/room/lists"

    ]
    for i in range(1, 20000):
        tasks.append(loop.create_task(send_post(domain + url_list[i % len(url_list)])))
    result = []
    for task in asyncio.as_completed(tasks):
        resp = await task
        result.append(resp)
    return result

def main():
    '''
    主入口
    :return:
    '''
    loop = asyncio.new_event_loop()
    asyncio.set_event_loop(loop)
    result = loop.run_until_complete(handler(loop))
    loop.close()

if __name__ == '__main__':
    main()

github: 最小环境示例

参考:

http://xiaobaoqiu.github.io/blog/2014/12/30/tomcat-access-logpei-zhi/

https://www.mail-archive.com/users@tomcat.apache.org/msg133479.html

https://stackoverflow.com/questions/57777941/disadvantages-of-setting-tomcats-recycle-facades-true

https://www.bianchengquan.com/article/605873.html

https://blog.csdn.net/Mr_SeaTurtle_/article/details/79274748

https://www.bianchengquan.com/article/605873.html

https://blog.csdn.net/q13145241q/article/details/107236217

https://bz.apache.org/bugzilla/buglist.cgi?bug_status=UNCONFIRMED&bug_status=NEW&bug_status=ASSIGNED&bug_status=REOPENED&bug_status=NEEDINFO&bug_status=RESOLVED&bug_status=VERIFIED&bug_status=CLOSED&email1=yilong.li%40runtimeverification.com&emailreporter1=1&emailtype1=exact&list_id=135106&product=Tomcat 6&product=Tomcat 7&product=Tomcat 8&query_format=advanced&resolution=FIXED&resolution=DUPLICATE

https://tomcat.apache.org/security-9.html

https://stackoverflow.com/questions/28950142/get-httpservletrequest-in-jsr-303-bean-validation

https://github.com/lovebugss/param-miss-demo

https://www.cnblogs.com/kismetv/p/8757260.html