Since upgrade to 2.0.1: IllegalStateException: InputStream has already been read

[mixcloud-downloader]

I upgraded a web application from Spring-boot-1.5.10 to 2.0.1. Since then I notice these frequent errors:

Apr 22 01:40:00 ru downloader.jar[7010]: 2018-04-22 01:40:00.083 ERROR 7030 --- [p-nio-80-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.IllegalStateException: InputStream has already been read - do not use InputStreamResource if a stream needs to be read multiple times] with root cause
Apr 22 01:40:00 ru downloader.jar[7010]: java.lang.IllegalStateException: InputStream has already been read - do not use InputStreamResource if a stream needs to be read multiple times
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.core.io.InputStreamResource.getInputStream(InputStreamResource.java:97)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.http.converter.ResourceHttpMessageConverter.writeContent(ResourceHttpMessageConverter.java:130)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.http.converter.ResourceHttpMessageConverter.writeInternal(ResourceHttpMessageConverter.java:124)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.http.converter.ResourceHttpMessageConverter.writeInternal(ResourceHttpMessageConverter.java:45)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:224)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:274)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.mvc.method.annotation.HttpEntityMethodProcessor.handleReturnValue(HttpEntityMethodProcessor.java:224)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:82)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:119)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:866)
Apr 22 01:40:00 ru downloader.jar[7010]:         at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851)
Apr 22 01:40:00 ru downloader.jar[7010]:         at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.servlet.resource.ResourceUrlEncodingFilter.doFilter(ResourceUrlEncodingFilter.java:60)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:158)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:126)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:111)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:84)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
Apr 22 01:40:00 ru downloader.jar[7010]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Apr 22 01:40:00 ru downloader.jar[7010]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Apr 22 01:40:00 ru downloader.jar[7010]:         at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
Apr 22 01:40:00 ru downloader.jar[7010]:         at java.lang.Thread.run(Thread.java:748)

The particular controller returns a ResponseEntity to download an InputStream. Also it seems only a fraction fails. Many download succeed. I know this report is not very helpful, but unfortunately I also don't know where to look further to get more details. Maybe this InputStreamResource sounds familiar to someone and can point me to a recent change with Spring-5.

[mixcloud-downloader]

The particular controller returns a ResponseEntity

Markdown ate ResponseEntity<InputStreamResource>

[snicoll]

point me to a recent change with Spring-5.

I think you can turn this into something very useful by extracting that controller in a sample app we can run ourselves and open an issue in the Spring Framework issue tracker. This discussion shouldn't really happen here given the stacktrace you've shared.

[mixcloud-downloader]

extracting that controller in a sample app we can run ourselves

Here's the thing:

Also it seems only a fraction fails. Many download succeed.

That sample app will not be of much a help, as it probably won't reproduce the issue. I't really nothing too exoctically. It's a Controller returing just said ResponseEntity<InputStreamResource> and most of the times it just works. I tried some edge cases locally, but without reproducing the issue. I can only observe it frequently with production traffic. Also the stacktrace is completely out of my application, so do you really thing such a sample application would be so helpful?

[snicoll]

Looking at what the controller does and the stacktrace might help the Spring Framework team to figure out what might cause this in Spring Framework 5 and not in Spring Framework 4.

[mixcloud-downloader]

True, I'll do that. I just hoped to avoid the hassle around submitting to your Jira.

[mixcloud-downloader]

For reference: https://jira.spring.io/browse/SPR-16754