Skip to content

IllegalStateException: InputStream has already been read when returning ResponseEntity<InputStreamResource> [SPR-16754] #21295

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
spring-projects-issues opened this issue Apr 22, 2018 · 12 comments
Closed

IllegalStateException: InputStream has already been read when returning ResponseEntity<InputStreamResource> [SPR-16754] #21295

spring-projects-issues opened this issue Apr 22, 2018 · 12 comments
Assignees
@bclozel
Labels
in: web Issues in web modules (web, webmvc, webflux, websocket) type: bug A general bug
Milestone
5.0.6

Comments

@spring-projects-issues
Copy link
Collaborator

spring-projects-issues commented Apr 22, 2018 •
edited
Loading

Jessy James opened SPR-16754 and commented

With the recent upgrade to Spring-Boot-2, also Spring-5 came in and I guess it is related to the upgrade from 4 to 5. So here's the issue. I have a controller which provides a download for the user by returning a ResponseEntity<InputStreamResource>. After the recent upgrade I now see frequently these errors in the log:

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)

I tried some scenarios locally and couldn't reproduce it. Also it happens not all the time, just sometimes it fails in said ways. The stack trace doesn't contain anything from my code. With Spring-Boot-1 I never had those errors.

This is an exemplary extract of my Controller:


	@RequestMapping(method = RequestMethod.GET)
	public ResponseEntity<InputStreamResource> download(@ModelAttribute("providerId") String providerId,
			@ModelAttribute("slug") String slug, HttpServletRequest request)
			throws IOException, SomeOfMyExceptions {
                // ...
                BodyBuilder builder = null; // Nice class name, 
                if (isPartial) {
			builder = status(PARTIAL_CONTENT);
			builder.header("Content-Range", range);

		} else {
			builder = ok();
			if (acceptsRange) {
				builder.header("Accept-Ranges", "bytes");
			} else {
				builder.header("Accept-Ranges", "none");
			}
		}

		builder.contentType(contentType);
		download.contentLength().ifPresent(builder::contentLength);
		download.etag().ifPresent(builder::eTag);
		download.lastModified().ifPresent(builder::lastModified);

		builder.header("Content-Disposition", String.format("attachment; filename=\"%s\"", filename));

		return builder.body(new InputStreamResource(stream));
}

Affects: 5.0.5

Reference URL: spring-projects/spring-boot#12939

Issue Links:

Referenced from: commits 72cfe41, e9a8a50
@spring-projects-issues
Copy link
Collaborator Author

Stéphane Nicoll commented

 extracting that controller in a sample app we can run ourselves

Can you please share a sample we can run ourselves? Just to make sure we can eliminate a maximum of potential sources. Writing code in a comment is not what I've had in mind. If you see "frequently" those errors, you should be able to provide a sample that can reproduce it. Thank you.

@spring-projects-issues
Copy link
Collaborator Author

Jessy James commented

I will provide an SSCCE in the hope that this will give any insights. However don't expect that to be any different from that sample code and also don't expect that to fail. I was not able to reproduce that issue locally. I can see those errors when I deploy the Boot-2 upgrade to production traffic and wait a few seconds to see some requests to fail. The thing is, this error clearly happens outside of client code. The last line of the sample is creating that InputStreamResource() and anything after that is framework land, which calls getInputStream() for a second time.

@spring-projects-issues
Copy link
Collaborator Author

Jessy James commented

I think I have something more useful now. This is the stack trace of a first getInputStream() (which doesn't fail):

Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.core.io.AbstractResource.contentLength(AbstractResource.java:146)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.http.HttpRange.toResourceRegion(HttpRange.java:63)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.http.HttpRange.toResourceRegions(HttpRange.java:180)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:201)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.mvc.method.annotation.HttpEntityMethodProcessor.handleReturnValue(HttpEntityMethodProcessor.java:224)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:82)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:119)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:866)
Apr 22 14:06:43 ru downloader.jar[14905]:         at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851)
Apr 22 14:06:43 ru downloader.jar[14905]:         at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.servlet.resource.ResourceUrlEncodingFilter.doFilter(ResourceUrlEncodingFilter.java:60)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:158)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:126)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:111)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:84)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
Apr 22 14:06:43 ru downloader.jar[14905]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Apr 22 14:06:43 ru downloader.jar[14905]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Apr 22 14:06:43 ru downloader.jar[14905]:         at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
Apr 22 14:06:43 ru downloader.jar[14905]:         at java.lang.Thread.run(Thread.java:748)

You see that this is a very different stack trace than the one for the second failing call. Also everything is related to AbstractResource.contentLength(). During my pre ticket research I noticed related tickets also discussing contentLength(). So was there a recent change in that space which could have introduced this regression?

@spring-projects-issues
Copy link
Collaborator Author

Jessy James commented

I can now successfully reproduce the issue. It happens only when continuing a download with a Range header. With this information I can happily create a SSCCE which will fail for ranged requests.

@spring-projects-issues
Copy link
Collaborator Author

Jessy James commented

Sorry, I was too curious, so I debugged it directly. There is HttpRange.toResourceRegion() which even says in the comment don't call InputStreamResource.contentLenght(), then the assertion fails and gets catched in AbstractMessageConverterMethodProcessor.writeWithMessageConverters(). To me it seems that Spring starts trying to handle range requests on InputStreamResource which it didn't before.

Generally I would welcome such a change, but this has to happen in collaboration with the client code. The framework can't just assume that
a) Range requests are supported,
b) content length is known (and even read the complete stream just to get that, which is here the issue)
c) deliver partial content without letting the client code know the offset (so that client code can skip on the origin stream as well)

@spring-projects-issues
Copy link
Collaborator Author

Jessy James commented

And here is your SSCCE: spring-attic/spring-framework-issues#178

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Apr 22, 2018 •
edited
Loading

Jessy James commented

I think 582014e944002609b562f6e4998935c06bbe6922 is the offending commit which references also #20344, #18407. So it really seems the framework now wants to support range requests on purpose. Then I suggest revising those tasks and addressing those three points I mentioned earlier:

A server MAY ignore the Range header field.

an origin server SHOULD send a Content-Length
header field when the payload body size is known
Also interesting in this context:

Any Content-Length field value greater than or equal to zero is
valid. I saw code which doesn't consider 0 as valid.

  • Client code needs to know the offset in case of a range request

@spring-projects-issues
Copy link
Collaborator Author

Zhang Jie commented

Spring will handle range request if only the request contains a valid Range header.

And else, InputStreamResource Should only be used if no other specific Resource implementation
is applicable acording to javadoc, prefer ByteArrayResource or FileSystemResource; or you can subclass InputStreamResource, custom subclass like this.

@spring-projects-issues
Copy link
Collaborator Author

Jessy James commented

Spring will handle range request if only the request contains a valid Range header
This is new (for InputStreamResource) and I don't think this is a good idea to let clients control the behaviour of the server. The RFC clearly states that a server may ignore such a header. With the new behaviour of the framework I cannot do this anymore. Range requests are not always supported. Furthermore you automatically add a "Accept-Ranges: bytes" response header (see the previous SSCCE with curl localhost:8080/ -v >> /dev/null). I don't want that always! Please, let me as a user decide when my application can handle that or not. Personally I have a real world application where I can't let the client control that. It's kind of a proxy where I do have to use whatever my origin is giving me.

InputStreamResource Should only be used if no other specific Resource implementation
is applicable
Yes and that's exactly my use case where we are in IllegalStateException land.

you can subclass InputStreamResource

I looked into that as I was looking for a workaround. I failed to see how:

  • I can ignore Range requests
  • Return no content length. Yes, that's also part of my use case as origin servers do deliver such responses. The API doesn't mention how to return that and every code around that doesn't seem to support that.
  • Know the offset and know that Spring will handle a ranged request, so that I can open my stream to origin with that offset as well. I can of course just read the range request and know the offset as I do it now, but then it is from the API totally unintuitive that Spring will wants a stream opened at an offset.

@spring-projects-issues
Copy link
Collaborator Author

Zhang Jie commented

Yes I agree with you, maybe it would be better that made range request handling configurable(default is "not ignore"). And also obey several MUST ignore(e.g. A server MUST ignore a Range header field received with a request method other than GET)

@spring-projects-issues
Copy link
Collaborator Author

Brian Clozel commented

I've just pushed a fix that should be shortly available in 5.0.6.BUILD-SNAPSHOT and 5.1.0.BUILD-SNAPSHOT builds.

This fix disables completely HTTP Range support if the return type is an InputStreamResource; initially we were relying on the conversion to ResourceRegion, but this had a couple of flaws:

  • we were still writing HTTP Range response headers, as we were trying to be flexible in case the Controller handler would return different Resource implementations
  • doing that, we were reading the content length of the resource, which reads the InputStream and triggers the exception described here

Now I feel that we got a little sidetracked here in the issue comments. I think that supporting HTTP Range requests when the return type is a Resource is a sensible opinion for a web framework. Even though the spec categorizes this as a "MAY", this doesn't mean we shouldn't try to do something here. I'd be curious to learn more about use cases where providing such a feature would harm an application in any way.

Please try the latest SNAPSHOT with your application and check back here with your findings. I'm closing this issue for now but I'm happy to discuss further improvements.

Thanks for the report! 

@spring-projects-issues
Copy link
Collaborator Author

Jessy James commented

The issue is fixed for me in 5.0.6.BUILD-SNAPSHOT. Thanks for the quick fix.

I'd be curious to learn more about use cases where providing such a feature would harm an application in any way.

I sure would love to have the framework handle all the ranged request logic. My use case is serving a stream from an origin server (think of a proxy). For that I have to handle ranged requests in the same way as the origin does. Some don't have a content length, some don't support ranged requests at all. I would of course appreciate any framework related support in this space.

@spring-projects-issues spring-projects-issues added type: bug A general bug in: web Issues in web modules (web, webmvc, webflux, websocket) labels Jan 11, 2019
@spring-projects-issues spring-projects-issues added this to the 5.0.6 milestone Jan 11, 2019
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@bclozel bclozel

Labels
in: web Issues in web modules (web, webmvc, webflux, websocket) type: bug A general bug
Projects
None yet
Milestone
5.0.6
Development

No branches or pull requests
2 participants
@bclozel @spring-projects-issues