在Spring异步方法中使用HttpServletRequest可能产生的问题

发表于 分类于 本文字数： 1.8k 阅读时长 ≈ 6 分钟

笔记

最近遇到了一个问题，在 Spring 的异步方法中 (@Async) 使用 HttpServletRequest 时，发现不仅在方法中无法通过 request.getParameter() 获取请求参数，而且甚至还影响到了后续请求，导致后续的有些请求也无法获取到请求参数。

复现

新建一个简单的 Springboot 项目，使用内置Tomcat 启动：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
// 添加注解：@EnableAsync 启用异步方法支持

// TestController.java
@RestController
public class TestController {

    private static final Logger LOGGER = LoggerFactory.getLogger(TestController.class);

    @Resource
    private AsyncService asyncService;
    // 计数器
    private AtomicInteger counter = new AtomicInteger(0);

    @RequestMapping("/test")
    public boolean test(HttpServletRequest request) throws Exception {
        String value = request.getParameter("value");
        int id = counter.incrementAndGet();
        LOGGER.info("recv...id: `{}`. value: `{}`. request: `{}`.", id, value, request);

        asyncService.async(id, request);

        return value != null;
    }

}


// AsyncService.java
@Service
public class AsyncService {

    private static final Logger LOGGER = LoggerFactory.getLogger(AsyncService.class);

    @Async
    public void async(int id, HttpServletRequest request) throws Exception {
        String value = request.getParameter("value");
        LOGGER.info("execute...id: `{}`. value: `{}`. request: `{}`.", id, value, request);


        Thread.sleep(5000);
    }

}

此时如果开始请求 /test 接口，可能会看到如下日志输出：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
2020-11-25 22:08:58.587  INFO 17980 --- [nio-8001-exec-1] o.example.web.controller.TestController  : recv...id: `1`. value: `1`. request: `org.apache.catalina.connector.RequestFacade@4bb8573f`.
2020-11-25 22:08:58.593  INFO 17980 --- [         task-1] org.example.service.AsyncService         : execute...id: `1`. value: `1`. request: `org.apache.catalina.connector.RequestFacade@4bb8573f`.
2020-11-25 22:08:58.933  INFO 17980 --- [nio-8001-exec-2] o.example.web.controller.TestController  : recv...id: `2`. value: `2`. request: `org.apache.catalina.connector.RequestFacade@4bb8573f`.
2020-11-25 22:08:58.934  INFO 17980 --- [         task-2] org.example.service.AsyncService         : execute...id: `2`. value: `2`. request: `org.apache.catalina.connector.RequestFacade@4bb8573f`.
2020-11-25 22:08:59.151  INFO 17980 --- [nio-8001-exec-3] o.example.web.controller.TestController  : recv...id: `3`. value: `3`. request: `org.apache.catalina.connector.RequestFacade@4bb8573f`.
2020-11-25 22:08:59.152  INFO 17980 --- [         task-3] org.example.service.AsyncService         : execute...id: `3`. value: `3`. request: `org.apache.catalina.connector.RequestFacade@4bb8573f`.
2020-11-25 22:08:59.483  INFO 17980 --- [nio-8001-exec-7] o.example.web.controller.TestController  : recv...id: `4`. value: `4`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:08:59.484  INFO 17980 --- [         task-4] org.example.service.AsyncService         : execute...id: `4`. value: `4`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:08:59.705  INFO 17980 --- [nio-8001-exec-8] o.example.web.controller.TestController  : recv...id: `5`. value: `5`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:08:59.706  INFO 17980 --- [         task-5] org.example.service.AsyncService         : execute...id: `5`. value: `5`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:08:59.953  INFO 17980 --- [nio-8001-exec-9] o.example.web.controller.TestController  : recv...id: `6`. value: `6`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:08:59.954  INFO 17980 --- [         task-6] org.example.service.AsyncService         : execute...id: `6`. value: `6`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:00.190  INFO 17980 --- [io-8001-exec-10] o.example.web.controller.TestController  : recv...id: `7`. value: `7`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:00.191  INFO 17980 --- [         task-7] org.example.service.AsyncService         : execute...id: `7`. value: `7`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:00.414  INFO 17980 --- [nio-8001-exec-1] o.example.web.controller.TestController  : recv...id: `8`. value: `8`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:00.415  INFO 17980 --- [         task-8] org.example.service.AsyncService         : execute...id: `8`. value: `8`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:00.678  INFO 17980 --- [nio-8001-exec-2] o.example.web.controller.TestController  : recv...id: `9`. value: `9`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:00.977  INFO 17980 --- [nio-8001-exec-3] o.example.web.controller.TestController  : recv...id: `10`. value: `10`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:01.196  INFO 17980 --- [nio-8001-exec-4] o.example.web.controller.TestController  : recv...id: `11`. value: `11`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:01.433  INFO 17980 --- [nio-8001-exec-6] o.example.web.controller.TestController  : recv...id: `12`. value: `12`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:01.668  INFO 17980 --- [nio-8001-exec-5] o.example.web.controller.TestController  : recv...id: `13`. value: `13`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:02.003  INFO 17980 --- [nio-8001-exec-7] o.example.web.controller.TestController  : recv...id: `14`. value: `14`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:02.318  INFO 17980 --- [nio-8001-exec-8] o.example.web.controller.TestController  : recv...id: `15`. value: `15`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:02.552  INFO 17980 --- [nio-8001-exec-9] o.example.web.controller.TestController  : recv...id: `16`. value: `16`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:02.775  INFO 17980 --- [io-8001-exec-10] o.example.web.controller.TestController  : recv...id: `17`. value: `17`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:02.988  INFO 17980 --- [nio-8001-exec-1] o.example.web.controller.TestController  : recv...id: `18`. value: `18`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:03.206  INFO 17980 --- [nio-8001-exec-2] o.example.web.controller.TestController  : recv...id: `19`. value: `19`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:03.535  INFO 17980 --- [nio-8001-exec-3] o.example.web.controller.TestController  : recv...id: `20`. value: `20`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:03.600  INFO 17980 --- [         task-1] org.example.service.AsyncService         : execute...id: `9`. value: `null`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:03.757  INFO 17980 --- [nio-8001-exec-4] o.example.web.controller.TestController  : recv...id: `21`. value: `null`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.
2020-11-25 22:09:03.936  INFO 17980 --- [         task-2] org.example.service.AsyncService         : execute...id: `10`. value: `null`. request: `org.apache.catalina.connector.RequestFacade@49991b6b`.

如果将异步任务线程池大小调整为1，并且在 controller 中模拟耗时操作，可能还会看到以下日志输出：

1
2
3
4
5
6
7
2020-11-25 22:27:06.056  INFO 18057 --- [nio-8001-exec-1] o.example.web.controller.TestController  : recv...id: `1`. value: `1`. request: `org.apache.catalina.connector.RequestFacade@19a174d`.
2020-11-25 22:27:06.062  INFO 18057 --- [         Task-1] org.example.service.AsyncService         : execute...id: `1`. value: `1`. request: `org.apache.catalina.connector.RequestFacade@19a174d`.
2020-11-25 22:27:08.454  INFO 18057 --- [nio-8001-exec-2] o.example.web.controller.TestController  : recv...id: `2`. value: `2`. request: `org.apache.catalina.connector.RequestFacade@19a174d`.
2020-11-25 22:27:10.810  INFO 18057 --- [nio-8001-exec-3] o.example.web.controller.TestController  : recv...id: `3`. value: `3`. request: `org.apache.catalina.connector.RequestFacade@19a174d`.
2020-11-25 22:27:11.062  INFO 18057 --- [         Task-1] org.example.service.AsyncService         : execute...id: `2`. value: `3`. request: `org.apache.catalina.connector.RequestFacade@19a174d`.
2020-11-25 22:27:13.160  INFO 18057 --- [nio-8001-exec-7] o.example.web.controller.TestController  : recv...id: `4`. value: `4`. request: `org.apache.catalina.connector.RequestFacade@4b0f6a2c`.
2020-11-25 22:27:15.392  INFO 18057 --- [nio-8001-exec-8] o.example.web.controller.TestController  : recv...id: `5`. value: `5`. request: `org.apache.catalina.connector.RequestFacade@4b0f6a2c`.

从上面日志中可以发现几个现象：

  • RequestFacade对象是可复用的(日志1)
  • 异步方法中通过 request.getParameter()可能无法获取到请求参数(日志1)
  • 异步方法中通过 request.getParameter()获取到的请求参数值可能与预期值不同(日志2)
  • 部分请求中，controller通过 request.getParameter()无法获取到请求参数(日志1)

其实后三个现象产生的原因都和第一个有关，接下来分析看看。

分析

HttpServletRequest 的管理由 Servlet 容器决定，如果容器要使用 Request对象池而不是为每个请求创建新的对象，可以节省创建对象成本，如果重用了 Request，则必须在请求结束后，清除对象上的旧数据，而以上的三个问题正是因为这个Request对象重用产生。

0. 获取请求参数方法

先看下 request.getParameter()方法：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
// org.apache.catalina.connector.Request.java

/**
 * Request parameters parsed flag.
 */
protected boolean parametersParsed = false;

// ......

@Override
public String getParameter(String name) {
    if (!parametersParsed) {
        parseParameters();
    }
    return coyoteRequest.getParameters().getParameter(name);
}

/**
 * Parse request parameters.
 */
protected void parseParameters() {

    parametersParsed = true;

    Parameters parameters = coyoteRequest.getParameters();
    boolean success = false;
    try {
        // ......
        success = true;
    } finally {
        if (!success) {
            parameters.setParseFailedReason(FailReason.UNKNOWN);
        }
    }

}

// ......
/**
 * Release all object references, and initialize instance variables, in
 * preparation for reuse of this object.
 */
public void recycle() {

    // .....
    parametersParsed = false;
    // .....
}

注意属性 parametersParsed，如果 parametersParsed 设置为了 false，则会调用方法parseParameters()将 parametersParsed 设置为 true，同时解析请求，将请求参数存入 Parameters(内部使用 LinkedHashMap 存储参数名和值之间的映射关系)。

在最后还能看到 recycle() 方法，根据注释可以看到该方法就是清除所有旧数据，从而可以让 Request对象可以复用，其中就包含了将参数解析标记parametersParsed重置，为下一次请求准备。由于参数获取是触发解析(也就是调用时判断是否解析，如果未解析，则处理)，因而如果在请求结束后，再对同一个 Request 获取参数，自然就有问题了。

1. 异步方法中可能无法获取到请求参数

这个就比较好理解了，因为调用方法时，请求已经结束， Request中已经没有任何请求信息，因而获取到的值为 null。

2. 请求可能无法获取到请求参数

由于在异步方法中调用了request.getParameter()，此时已经对该 Request 对象进行了参数解析，并且将parametersParsed设置为已解析，而由于对 Request 的重用，同时参数获取是触发解析的，所以即使设置请求对象，也无法再次进行参数解析，因而请求获取到参数都为 null。

3. 异步方法中获取到的请求参数值与预期值不同

这个和上一点类似，如提交异步方法时，id=1 -> Request1，如果该方法执行时， Request1 已经被修改了(如异步方法进入了线程池队列，在执行之前，Request1重用了)，那就有可能期望获取的值和实际值不同。