Problem
I have a handler for a post request, the response can take a while so I stream it. If the response takes too long I get a AsyncRequestTimeoutException, which I handle via my @ControllerAdvice handler. The problem is that once I get that error, the very next connection that comes in gets an error when trying to connect.
curl:
(52) Empty reply from server
postman:
Error: socket hang up
In the server I do see the following log message when the connection comes in
2020-10-13 11:53:26.090 INFO 22536 --- [nio-8080-exec-7] o.a.catalina.connector.CoyoteAdapter : Encountered a non-recycled response and recycled it forcedly.
org.apache.catalina.connector.CoyoteAdapter$RecycleRequiredException: null
at org.apache.catalina.connector.CoyoteAdapter.checkRecycled(CoyoteAdapter.java:525) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.coyote.http11.Http11Processor.recycle(Http11Processor.java:1364) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.release(AbstractProtocol.java:1072) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
Looking at the CoyoteAdapter this appears to be an informational message, and there is no indication that the incoming connection will not be handled.
Question
What do I need to do in order to get Spring Boot/Tomcat to handle the next request properly after getting the AsyncRequestTimeoutException (NOTE: The AsyncRequestTimeoutException is expected in some cases, so I'm not concerned with that. I have already set spring.mvc.async.request-timeout to where I want it).
System
My System is Mac OSx but is duplicated in a Docker Container (openjdk:11-jre-slim)
Spring Boot: 2.3.4.RELEASE (which has Tomcat 9.0.38 embedded)
Sample App
Created with Spring Iniatlizr using only spring-boot-starter-web
Controller code to duplicate
@RestController
@RequestMapping("/test")
public class MainController {
private final static Logger log = LoggerFactory.getLogger(MainController.class);
private final ObjectMapper jsonMapper;
private final Random random;
@Autowired
public MainController(ObjectMapper jsonMapper) {
this.jsonMapper = jsonMapper;
this.random = new Random();
}
@PostMapping(value = "streamIt", produces = MediaType.APPLICATION_JSON_VALUE)
public ResponseEntity<StreamingResponseBody> streamIt(@RequestBody final List<Integer> param) {
log.info("streamIt starting with {} requests", param.size());
// Stream the response, this way the request shouldn't time out if there
// are a lot of elements in the passed in param list.
StreamingResponseBody stream = out -> {
LocalDateTime start = LocalDateTime.now();
try {
// Start the array out
out.write('[');
// flag to indicate if we have to add a comma for array separation
boolean firstItemWritten = false;
for (final Integer request : param) {
if (!firstItemWritten) {
firstItemWritten = true;
} else {
log.debug("Writing comma!");
// Write a comma to the stream
out.write(',');
}
Response response = calculateResponse(request);
out.write(jsonMapper.writeValueAsString(response).getBytes());
out.flush();
log.debug("Wrote value.");
}
} catch (IOException io) {
log.error("Caught io exception");
} finally {
out.write(']');
try {
out.close();
} catch (Exception ioe) {
log.warn("Exception closing StreamingResponseBody," +
" error=\"{}\"", ioe.toString());
}
log.info("streamIt exiting, it took {}.", Duration.between(start, LocalDateTime.now()));
}
};
return new ResponseEntity<>(stream, HttpStatus.OK);
}
private Response calculateResponse(Integer request) {
// Randomly get a "calculation" delay between 15ms and 500ms
long sleep = Math.max(15L, random.nextInt(500));
log.debug("Sleeping {}ms for request={}", sleep, request);
try {
Thread.sleep(sleep);
} catch (InterruptedException e) {
// I do get this error logged, but this would not
// happen in my actual app since I don't really do a 'sleep'
log.error("Caught interrupted exception pretending to calculate response...");
}
return new Response(request);
}
}
Curl command to duplciate issue
curl --request POST 'localhost:8080/test/streamIt' --header 'Content-Type: application/json' --data-raw '[0,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,
0,-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,
0,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,
0,-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,
0,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,
0,-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,
0,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,
0,-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,
0,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,
0,-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]'
Thank you