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

笔记

最近遇到了一个问题,在 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
// 添加注解:@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重用了),那就有可能期望获取的值和实际值不同。