Bug 64762 - CoyoteInputStream getInputStream() read (wait after premature end and the rest comes)
Summary: CoyoteInputStream getInputStream() read (wait after premature end and the res...
Status: RESOLVED WORKSFORME
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Connectors (show other bugs)
Version: 9.0.31
Hardware: PC Linux
: P2 regression (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-09-23 13:24 UTC by ll
Modified: 2021-06-09 08:40 UTC (History)
2 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description ll 2020-09-23 13:24:35 UTC
Hi everyone

Since the upgrade from Tomcat 8 to tomcat 9 The CoyoteInputStream.getInputStream() does not work properly anymore.

We run Debian 10 buster and Tomcat has the following ServerInfo:
Server version: Apache Tomcat/9.0.31 (Debian)
Server built:   Jul 15 2020 11:43:33 UTC
Server number:  9.0.31.0
OS Name:        Linux
OS Version:     4.19.0-10-amd64
Architecture:   amd64
JVM Version:    1.8.0_261-b12
JVM Vendor:     Oracle Corporation

When reading/uploading  larger files (i.e. a HTTPS form-post) it looks like not everything is copied as it should, we get the following Stack
Trace:
org.apache.commons.fileupload.MultipartStream$MalformedStreamException: Stream ended unexpectedly
	at org.apache.commons.fileupload.MultipartStream$ItemInputStream.makeAvailable(MultipartStream.java:1033)
	at org.apache.commons.fileupload.MultipartStream$ItemInputStream.read(MultipartStream.java:931)
	at java.io.InputStream.read(InputStream.java:101)
	at org.apache.commons.fileupload.util.Streams.copy(Streams.java:98)
	at org.apache.commons.fileupload.util.Streams.copy(Streams.java:68)
	at  …
	at org.apache.commons.chain.impl.ChainBase.execute(ChainBase.java:191)
	at org.apache.commons.chain.generic.LookupCommand.execute(LookupCommand.java:305)
	at org.apache.commons.chain.impl.ChainBase.execute(ChainBase.java:191)
	at …
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:660)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.filters.CorsFilter.handleNonCORS(CorsFilter.java:352)
	at org.apache.catalina.filters.CorsFilter.doFilter(CorsFilter.java:171)
…
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.filters.ExpiresFilter.doFilter(ExpiresFilter.java:1227)
…
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.valves.SemaphoreValve.invoke(SemaphoreValve.java:160)
	at com.privasphere.net.SemaphoreValve5340.invoke(SemaphoreValve5340.java:43)
	at org.apache.catalina.valves.CrawlerSessionManagerValve.invoke(CrawlerSessionManagerValve.java:235)
	at com.privasphere.net.CrawlerSessionValve5340.invoke(CrawlerSessionValve5340.java:50)
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:688)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1639)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)


Our (surprising) workaround for now is as follows:. We look at how many bytes are expected by request.getContentLength() and if what is read does not match the expected size sleep some milli seconds. We do this in a while loop which is iterated a maximal number of times or until everything is read. Normally this solves the problem. So for example for an upload of 230 K, the inputstream claims done after ~130K, after a few ms wait, another 100K appear and all works fine.

Could you please have a look into that bug?
Comment 1 Ralf Hauser 2020-09-23 14:20:57 UTC
The stream is read/copied with

org.apache.commons.io.IOUtils.copy()

In combination with Axis2, the soap client side sees 

"Unexpected EOF in prolog"  

(there we haven't found the symptom fighting workaround yet, but we rather want to *really solve it*)
Comment 2 Christopher Schultz 2020-09-23 14:52:47 UTC
Looks like you are doing multipart/form-data processing, as handled by commons-fileupload. Is that using the Tomcat-provided Servlet-3.0 file-upload, or are you using a different mechanism?

I would guess it's Tomcat, but Tomcat doesn't use commons-chain, so I'm wondering what's happening, here.

You say this is an "asynchronous read" but you are using an InputStream, which is a blocking stream. What do you mean by "asynchronous read"?
Comment 3 Ralf Hauser 2020-09-23 15:12:38 UTC
No, we are not using "Tomcat-provided Servlet-3.0 file-upload" but commons-fileupload-1.4.jar with launched by some legacy struts

"asynchronous" may be confusing - it is blocking, but after one thinks it is done, more appears in the inputstream
Comment 4 Christopher Schultz 2020-09-23 15:26:20 UTC
(In reply to Ralf Hauser from comment #3)
> No, we are not using "Tomcat-provided Servlet-3.0 file-upload" but
> commons-fileupload-1.4.jar with launched by some legacy struts

Okay, so Struts is handling the file-upload. I suspected as much because of the use of commons-chain.

Is your code being used *at all* in this interaction, or is Struts handling the file upload completely by itself.

> "asynchronous" may be confusing - it is blocking, but after one thinks it is
> done, more appears in the inputstream

It would be strange for an InputStream to return -1 from a read and then later allow more reading. Is that really what you are observing?
Comment 5 mgrigorov 2020-09-24 08:42:35 UTC
Can you reproduce this without Struts ? I.e. with plain Servlet
Comment 6 Mark Thomas 2020-09-24 08:46:24 UTC
Whether it requires Struts or not, a *minimal* WAR (with source) that allows us to reproduce this would be very helpful.
Comment 7 Ralf Hauser 2020-09-24 09:34:16 UTC
(In reply to mgrigorov from comment #5)
> Can you reproduce this without Struts ? I.e. with plain Servlet

Yes, it happens also with the Axis2 Servlet where there is no struts in-between.

As the CoyoteInputStream.markSupported() returns false from the parent java.io.InputStream.java this only happens upon the first read of the stream

We'll provide more insights and possible some code once we progress further - many thanks for the quick responses
Comment 8 Mark Thomas 2020-09-29 11:55:09 UTC
Also, make sure you test against the latest 9.0.x release. There are a couple of fixes that might relate to this since 9.0.31.
Comment 9 Mark Thomas 2020-10-29 19:28:45 UTC
This issue has been in the NEEDINFO state for a month now.

Without sufficient information to reproduce the issue this will eventually get closed.
Comment 10 Mark Thomas 2020-12-01 09:33:55 UTC
Another month has passed and we still don't have a minimal WAR that reproduces this issue. I'll leave this open another month but without a test case to investigate this will get closed.
Comment 11 Ralf Hauser 2020-12-19 09:06:10 UTC
The problem still persists, albeit we were able to almost make it disappear

We no longer wait a limited amount of sleep iterations, but "forever" (provided the browser declares "content-length").
Reasoning: we are on a quick fiber network and most of the affected users normally are on arbitrary (slow) home-office networks and only experience it intermittently.
So if we don't wait forever, they will see an error, so we better wait until their browser-timeout anyway and hopefully get the last expected packets before that happens.



Another strange, but also locally reproduceable phenomenon is that normally
HttpsServletRequest request.getAttribute("javax.servlet.forward.request_uri") is not null, but under certain circumstances it is null.
In this case request.getRequestURI() which eventually gets to org.apache.coyote.Request.requestURI() still has the value sought.

Further analysis show that if HttpsServletRequest is instantiated by 
org.apache.catalina.core.ApplicationHttpRequest the attribute has a value but if it is rg.apache.catalina.connector.Request (inside org.apache.catalina.connector.RequestFacade), all its source of attributes are empty (specialAttributes, attributes, coyoteRequest.getAttribute()) i.e. null
Comment 12 Mark Thomas 2021-02-23 13:53:40 UTC
As per my comment from December, without a test case that demonstrates the issue I am resolving this issue as works for me.

I have simulated an POST over a slow network to an NIO HTTPS port and I do not see any errors. Without a test case that demonstrates the issue, the conclusion is that this is not a Tomcat issue.

Should a test case be found that demonstrates this bug on a clean install of the latest 9.0.x release then please do re-open this issue and add the test case so it can be investigated.
Comment 13 Ralf Hauser 2021-06-09 08:40:24 UTC
Got lots of inputstream truncation problems with SAML-Tickets and SOAP-UI lately (pausing didn't help anymore).

Saw http://mail-archives.apache.org/mod_mbox/tomcat-users/202003.mbox/%3CCAMomwMoNVUjg2QyeWFSYr34OGn5MbBYBX-wyW4kcd_JsY7TJMg@mail.gmail.com%3E

Upgraded to 9.0.43 and the all problems seem to be gone!

(Strange that debian still advertizes v9.0.31 as "good" for the "stable" release ?!?)