Lockup processing POST request body with Jetty 12.0.1 using http/2 #10513
Comments
ghost
added
the
|
You have to finish reading from the HTTP stream. All your code is doing is iterating through the Zip directory/dictionary/index for entries, and reading the entry content. How do you fix this? See TODO in the code snippet below. val in = request.getInputStream
val zip = new ZipInputStream(in)
var entry = zip.getNextEntry
while (entry != null)
{
val out = new CountingOutputStream(new NullOutputStream)
zip.transferTo(out)
out.close
System.err.println(entry.getName + ":" + out.bytesWritten)
entry = zip.getNextEntry
}
zip.close
// TODO: you need to finish reading from `in` here, the HTTP stream is not yet complete, just the ZIP content is.
// You have to choose a behavior here,
// eg: if there is content, do you fail the upload? or ignore it the extra content? warn the user?
// small amounts of content ok? large amounts of extra content show a problem?If you don't want to do this, you can send the Zip stream in a |
|
@joakime actually I had a chat with @sbordet about this and I think we should probably do a So if there is never any blocking between the end of the last zip entry and then end of the stream, then that "fix" should help @silviobierman. However, if there sometimes in content that could block, then that fix will not help and @silviobierman should read to EOF after the last entry. Thus to be safe, I think both should be done. |
|
that we used to do this in the past, and nefarious actors abused it, they would just hit resources on the server that would respond quickly (usually a rejection of some kind, auth, invalid params, etc), and then the |
|
then there were examples of non-nefarious actors, but just bad requests (bad to the webapp, not jetty). Example 1: Example 2: |
|
we also don't want to combine |
|
@joakime it should be a consumeAvailable, not a consumeAll. I.e. it will never block. It will just keep reading until null (a stall) or EOF. If it stalls before EOF, then it will fail the stream like it does now. |
|
Note that ultimately, HTTP/1.1 semantics puts us into |
|
While we should thinking about HTTP/1 behaviors, I note that this issue is opened against HTTP/2 |
|
We do |
|
Sorry I replied to @joakime on the mailing list instead of here. Let me repeat here: You talk about the code in the alternative servlet TestServlet2 that treats the POST body as a ZIP. As posted the code however uses TestServlet1 that simply uses input.transferTo to read and discard all bytes of the POST body without making any assumptions about the content. This results in the same lockup for any large enough POST with any type of data. I get the same result when posting the content of a 80M MP4 file. So although I understand your point about reading the complete body when parsing input in some format while reading the request that is not the cause of the issue. I merely posted the second servlet because it demonstrates that the first part of the request body is read properly, printing out the name/size of several initial entries in a posted ZIP file and then stalling. |
|
We are tracking some reports of whole JVM lockups on JDK 21 from various persons ATM. Can you test on JDK 20 or JDK 17 and see if you still have lockups? |
|
I already was quite sure I saw this behavior before I upgraded my OpenJDK 20 to 21 a few days ago. But to be sure I just uninstalled 21 and installed 17. Same results with both JDK versions: lockup with my 12.0.1 test code and no issues with our application using Jetty 11. |
|
Additional note: this is not an intermittent issue. Each POST fails 100% of the time if the body is large enough. Start server, run curl post command line, lockup. |
fixed #10513 ContentSourceInputStream close by making it consume available content whilst seeking EOF
|
@silviobierman Can you take some thread dumps during the stall? |
|
Well, this is interesting. Over the weekend I upgraded my system to Fedora 39 (beta) and got new versions of OpenJDK 21, VSCode, SBT (the Scala build tool and debugger) and curl. Now the lockups with TestServlet1 (reading plain content bytes) and TestServlet2 (reading content with ZipInputStream) using the same test method/content can not be reproduced. They would occur consistently before and now these test cases work as expected. It is not caused by the new JDK only because reverting to OpenJDK17 still does not make the issue reappear. One lockup still remains: trying to read a POST body as a multipart form-data (both with browser and curl as client). I traced the handling code to the request.getParts call and that never returns. I changed the standalone test code to add a MultipartConfigElement using ServletHolder.setMultipartConfig and changed the POST handling code to call request.getParts. Should I file a separate issue for that with the current test code and close this one? Or is it better to continue here? |
|
@silviobierman interesting?!?!? Continue here as we never got a good diagnosis, so it could be same problem just tickled a different way. |
|
The current test code: import java.io._
import java.util.zip._
import jakarta.servlet._
import jakarta.servlet.http._
import org.eclipse.jetty.alpn._
import org.eclipse.jetty.alpn.server._
import org.eclipse.jetty.http2._
import org.eclipse.jetty.http2.server._
import org.eclipse.jetty.http3._
import org.eclipse.jetty.http3.server._
import org.eclipse.jetty.util.resource._
import org.eclipse.jetty.security._
import org.eclipse.jetty.server._
import org.eclipse.jetty.server.handler.{ ContextHandler, ResourceHandler, DefaultHandler, ContextHandlerCollection }
import org.eclipse.jetty.ee10.servlet._
import org.eclipse.jetty.session.{ DefaultSessionIdManager, HouseKeeper }
import org.eclipse.jetty.util.security._
import org.eclipse.jetty.util.ssl._
import org.eclipse.jetty.util.thread._
import org.eclipse.jetty.server._
import org.eclipse.jetty.websocket.api._
import org.eclipse.jetty.ee10.websocket.server._
import org.eclipse.jetty.ee10.websocket.server.config._
import org.eclipse.jetty.http.HttpFields
class NullOutputStream extends OutputStream
{
def write(byte : Int) = ()
override def write(buff : Array[Byte]) = ()
override def write(buff : Array[Byte],start : Int,count : Int) = ()
}
class CountingOutputStream(wrapped : OutputStream) extends OutputStream
{
private var written : Long = 0
def bytesWritten = written
def write(byte : Int)
{
wrapped.write(byte)
written += 1
}
override def write(buffer : Array[Byte],offset : Int,bytes : Int)
{
wrapped.write(buffer,offset,bytes)
written += bytes
}
override def write(buffer : Array[Byte])
{
wrapped.write(buffer)
written += buffer.length
}
override def flush = wrapped.flush
override def close = wrapped.close
}
class TestServlet3 extends HttpServlet
{
override def doPost(request : HttpServletRequest,response : HttpServletResponse)
{
System.err.println(request.getRequestURL().toString)
var hdrs = request.getHeaderNames
while (hdrs.hasMoreElements)
{
val n = hdrs.nextElement
val v = request.getHeader(n)
System.err.println(n + "=" + v)
}
System.err.println("TRY GET PARTS")
val parts0 = request.getParts
System.err.println("SUCCEEDED GET PARTS")
val parts = parts0.toArray.toIndexedSeq.map(_.asInstanceOf[Part])
for (part <- parts)
{
val in = part.getInputStream
val out = new CountingOutputStream(new NullOutputStream)
in.transferTo(out)
in.close
out.close
System.err.println("PART1:" + part.getName() + "/" + out.bytesWritten + "/" + part.getSize())
}
val writer = response.getWriter
writer.println("Thank you")
writer.close
}
}
object JettyTest
{
def main(args: Array[String])
{
val pool = new QueuedThreadPool
val server = new Server(pool)
// Create connector
val keyStore = "xxx.jks"
val keyPassword = "xxx"
val sslContextFactory = new SslContextFactory.Server
sslContextFactory.setEndpointIdentificationAlgorithm("HTTPS")
sslContextFactory.setKeyStorePath(keyStore)
sslContextFactory.setKeyStorePassword(keyPassword)
sslContextFactory.setKeyManagerPassword(keyPassword)
sslContextFactory.setKeyStoreType("JKS")
val httpsConfig = new HttpConfiguration
httpsConfig.setSecureScheme("https")
httpsConfig.setSecurePort(8443)
val http1 = new HttpConnectionFactory(httpsConfig)
val http2 = new HTTP2ServerConnectionFactory(httpsConfig)
val alpn = new ALPNServerConnectionFactory
alpn.setDefaultProtocol(http1.getProtocol)
val ssl = new SslConnectionFactory(sslContextFactory,alpn.getProtocol)
val http2Connector = new ServerConnector(server,ssl,alpn,http2,http1)
http2Connector.setHost("0.0.0.0")
http2Connector.setPort(8443)
http2Connector.setIdleTimeout(1800000L)
server.addConnector(http2Connector)
// Create Servlet context
val servletContext = new ServletContextHandler
servletContext.setContextPath("/")
val holder = new ServletHolder(classOf[TestServlet3])
val mc = new MultipartConfigElement(System.getProperty("java.io.tmpdir"),500000000,500000000,500000000)
holder.getRegistration.setMultipartConfig(mc)
servletContext.addServlet(holder,"/*")
// Setup server
val ctxHandler = new ContextHandlerCollection
ctxHandler.setHandlers(servletContext)
server.setHandler(ctxHandler)
server.start
server.join
}
}And this is the dump after posting Multipart form data containing as only part a ZIP-file of ~26Mb size. |
|
@silviobierman any chance of getting a server dump as well (see https://eclipse.dev/jetty/documentation/jetty-12/operations-guide/index.html#og-troubleshooting-dump) @lachlan-roberts can you glance at this one to see if you can see anything? |
|
@silviobierman also any chance of a run with either full debugging turned on, or perhaps just |
|
@silviobierman sorry to pepper you with questions... but.... at the point that you call getParts, do you know the type of the request? Is it a |
|
Now just some thinking out loud... I'm expecting @silviobierman to say that the request is-a But if it were, what thread should that be... ah it would be the main thread calling org.eclipse.jetty.ee10.servlet.ServletMultiPartFormData#from(jakarta.servlet.ServletRequest, java.lang.String). So either we are in an async setup and the data is not coming in (or not demanded) OR we were in a blocking setup and somehow we returned from @lachlan-roberts thoughts? |
|
@gregw I think we can see from the thread dump that the request is a So I suspect we read a null content chunk and then for some reason the demand callback was never called. |
|
I printed the actual class name of the request object which is org.eclipse.jetty.ee10.servlet.ServletApiRequest so you where right about that. The command line I use for the POST request is: curl -F "file=@/home/silvio/Downloads/20181121_105432.mp4" https://localhost.jambo-mobile.com:8443 but the MP4 (78M) can be swapped with any sufficiently big file. I get the same result with largish ZIP files (26M and 307M). The localhost.jambo-mobile.com is equivalent to 127.0.0.1. I ran the test with -Dorg.eclipse.jetty.LEVEL=DEBUG and got quite some outp[ut whith I attached here. |
|
@gregw: I ran JMC but the Mbean tree does not show anything Jetty related. I am sure I need to do something to enable JMX but could not find anything on how to do that with embedded Jetty. Any pointers? |
|
@silviobierman See https://eclipse.dev/jetty/documentation/jetty-12/operations-guide/index.html#og-jmx if you are using a standard deployment setup... which I'm guessing you are not. Server server = new Server();
// ...
MBeanContainer mbContainer = new MBeanContainer(ManagementFactory.getPlatformMBeanServer());
server.addBean(mbContainer);@lachlan-roberts Can you look at trying to make a reproducer? I'll have a look at the debug log. |
|
I would like to reiterate this issue. Jetty12 has been in production use with us for almost two weeks now. Apart from some minor glitches everything seemed to work fine and general performance appears better than with Jetty11. BUT: Ever since the upgrade about 50% of a dozen automated nightly uploads to our system existing of HTTP POSTS containing plain CSV data (text/csv) fails. It took some time for the users to notice the lack of new data and for us to find out where things are going wrong. These processes have been in place for years without similar issues. Since the uploads come from several different external systems we currently have little details about the way they are performed. Each time the first step on the server side is reading the POST payload and writing it to a file. In half the cases this process blocks indefinitely. Stopping the server process many hours later results in IO exceptions that have stack traces linking to the processing application code. We will add logging of the HTTP headers to find out more about the issue. It could be that some feeds use chunked encoding while others don't. Some might use HTTP/1.1 while some might use HTTP/2. Etc. But since the processes are critical to our users we have little time to investigate this. We may have to revert to a Jetty11 based version within a day or two. I will report back when I have more info. |
|
BTW: We are using 12.0.3. |
|
@silviobierman can you please open a new issue and add more details if you can? Is it a multipart request? Please report all that in the new issue. |
|
@silviobierman Also a server dump would be very useful, so we can see what state those connections are in. Also stack traces of exactly where those reads are blocked. |
|
Sorry for continuing on this issue but it will take me quite some time to collect all the info needed for opening a new issue, BUT: Looking at the now logged headers revealed that all the blocking POSTs have Expect: 100-continue whereas the succesful ones don't. Is there something the application code should/could do when such a request comes in instead of simply attempting to read the payload like the application code does now? The interesting thing is that doing this sometimes does result in part of the expected content but mostly blocks with zero bytes received. |
|
@silviobierman are you using Servlet APIs in your application, or Jetty 12 Handler APIs? |
|
This is Servlet API, Jetty-ee10, HTTP/2. |
|
@silviobierman the way that 100-continues is meant to work is:
So the first question is: can you tell if a 100-Continue response is being sent? |
|
I have logged the POST request headers at the start of the handling code. The 100-Continue header is certainly present in the problem cases. All subsequent logging is done after attempting to write the bytes to a temp-file (using transferTo on the request.getInputStream wrapped in a BufferedInputStream). In the cases where the 100-Continue is present the transferTo locks up and nothing else is logged. |
|
Sorry for misreading, forget about my last response. I can not tell if a 100-Continue response is being sent. I can only see the headers coming in. |
|
@silviobierman we are definitely going to need more information. We do have tests with 100-Continues over h2 and they pass fine. I have tried some variations on them, including pausing during the transmission of the body, and they still pass fine. So it is something else plus 100 Continues that is causing the failure. Do any Expect 100 Continues requests work for you? Is it just some that fail? How large are they? What is the content type? What is doing the read and transfer to disk? |
|
@silviobierman I have created #10956 in which you can post additional information. I have already started cleaning up the implementation and adding more tests, but I have not yet found a reproducer for your issue. Let's talk more in the other issue. |
|
Thanks. For now I was forced to revert that specific server to a previous version that uses Jetty11 so I will have to try and reproduce the issue myself. I will report back in #10956. |
|
When trying to setup a test environment I encountered further errors with Jetty12. Our backup process consists of pulling a large ZIP archive from the application via a GET request. A restore (which I wanted to do to create a test environment) is done by POSTing the same ZIP back into the application (either through a FORM post or a plain ZIP payload). With Jetyy12 this fails in most if not all cases with all kinds of errors from the ZIPInputStream that byte counts are off, block sizes are invalid etc. As before, reverting to Jetty11 makes the problems go away. Somehow this just did not come up since the move to Jetty12 so I was focussing on the 100-continue issue. Since I think the problem is not purely about 100-continue I guess the issue created by Greg is not the right place to discuss this further. I am sorry I do not have more details right now. But the general picture is that all kinds of POST requests (both FORM and non-FORM) fail with larger payloads. It does not happen in one particular place but all over our system. As said earlier, all application code has been in place for years with Jetty versions 6-11 without any such issues. We have been using http/2 since it was supported by Jetty. If I remember correctly that was with Jetty9 but I could be wrong. I will investigate further. Previous tests revealed that reverting to http1.1 with Jetty12 worked correctly but that is not the way we want to go. Therefore we have reverted everything to Jetty11 for now. |
|
I'm reopening this issue just to record that there is something we need to look at and it looks different to 100-continues. @silviobierman can you confirm that it is jetty-12 h2 that is having these issues? or are you seeing them on jetty-12 HTTP/1.1 as well? When you say "large", can you give us an estimate 10MB? 1GB? Whose ZIPInputStream has the errors? Is this our GzipHandler that is doing the inflating or something else? Is the content a multipart form and then gzipped or a multipart form that has zip payload parts? |
|
I've just discovered a bug in this codepath that may or may not explain this problem: #11022 @silviobierman if you could come up with a reproducer, this would be invaluable to quickly figure out what the problem is and fix it. Barring that, it would be helpful if you could reduce the scope of possibilities (answering @gregw's questions would help a lot) and if you could try a build with my fix for #11022. Thanks! |
|
The problem is with Jetty 12.0.3 ee10 HTTP/2. The issue with the Expect:100-continue datafeeds is a plain POST with text/csv content. The other problem I described is with a JavaScript FormData originated FORM POST with a single part that contains ZIP content. No unzipping by Jetty, the application wraps with it's own ZipInputStream based on the content-type. As is the exception thrown is: java.util.zip.ZipException: invalid stored block lengths When disabling HTTP/2 and using HTTP 1.1: java.util.zip.ZipException: invalid entry size (expected 585999 but got 585994 bytes) Using Jetty 11.0.15 both variants work without issue. Bigger roughly means ranging between 30Mb and a couple of Gb. This is the FORM POST case. The external datafeed plain POSTs are all smaller then 50Mb. I am downloading branch jetty-12.0.x now to do a build and try again. Soon to be continued. |
|
I did the following: $ git clone --branch jetty-12.0.x https://github.com/jetty/jetty.project and retried with the resulting jetty-12.0.4-SNAPSHOT JARs. Unfortunately this gave the same results. Because of my current workload I will not be able to isolate this into an isolated test case anytime soon. The application code is quite complex since the handler code that extracts the ZIP is quite complex handling multiple special cases inside the ZIP, some of which is recreating H2 databases from custom backup-formats (inside nested ZIPs) and traversing multiple other cases of nested ZIP elements. The extracting itself is large and linked to thousands of lines of application code (which, to make matters worse, is all in Scala). But anything you want me to try/test I will try to fit in. |
Note that ZipInputStream and GzipInputStream do not read to EOF. Once you are done with the Zip/Gzip document you'll have to continue reading from the raw stream to trigger the EOF. (especially important on HTTP/1.1 with persistent connections, doubly so if the Transfer-Encoding chunked is in play) |
|
Also note that Jetty's GzipHandler can uncompress request body content, you don't need to add a hack to do it yourself. You just need to specify an inflate buffer size on the GzipHandler for it to start to be used. (set it to 8192 and you'll be good) GzipHandler gzipHandler = new GzipHandler();
gzipHandler.setInflateBufferSize(8192); // enable request body inflation (aka decompression) |
@silviobierman I don't think we have found a smoking gun for these problems, but we have found a number of issues that can definitely be improved. We will get fixes for those merged in the next few days and then ask you to try again. |
@joakime I think the issue is that the request is multi-part with a single part that is a compressed file. So the jetty GzipHandler will not see it, as we do not decompress within the parts. |
A prior comment does not indicate multipart is in use - #10513 (comment) |
|
My understanding is that the zipped content can be uploaded either by multipart form content, or as a "plain ZIP upload". However, the problem "described is with a JavaScript FormData originated FORM POST with a single part that contains ZIP content. No unzipping by Jetty" The errors seen suggest some corruption of the part, which could be the single byte read issue that @lorban is fixing. The hangs could be the fact that we are not resetting the h2 stream with a NO_ERROR reset, so end up waiting for content that will not be sent. |
|
@joakime @gregw : The ZIP-archives are generated by the reverse process in the GET-handler. All tests I have done revealed that reading all its entries fully in the POST-handler left 0 bytes at the end of the request/part. And this is not about transfer encoding with gzip but simply content types that happen to be (sometimes nested meaning ZIP inside ZIP) ZIP-archives which are processed by the application in several different ways depending on context and content. Correct me if I am wrong but I was under the assumption that it is the containers responsibility to keep up the notion of separate independent requests meaning it will drop unprocessed bytes after something like a synchronous doPost returns or throws and not let them leak through into subsequent requests. |
|
There is a common trait in all these cases: the server needs considerable time to process the data and does not buffer it to finish the request early. The back pressure results in a client (in my ZIP-archive test case being the browser) waiting sometimes several minutes up to even 45-60 minutes in extreme cases for the server to accept all the data. The CSV feeds that went wrong for the Expect:100-continue clients (ie. .NET clients) cases take much less time in the range of 10-30 seconds. |
|
I think we are looking at several problems here. We will soon have some new images for you to test. stand by... |
Jetty version(s)
12.0.1
Jetty Environment
ee10 / http/2
Java version/vendor
(use: java -version)OpenJDK Runtime Environment (Red_Hat-21.0.0.0.35-1.rolling.fc38) (build 21+35)
OpenJDK 64-Bit Server VM (Red_Hat-21.0.0.0.35-1.rolling.fc38) (build 21+35, mixed mode, sharing)
OS type/version
Fedora 38 Workstation
Description
This application sets up an embedded Jetty 12.0.1 instance with one servlet class TestServlet1. The doPost method simply tries to read-and-discard the content of the body before sending a short response.
Posting a sufficiently large file to the application will result in a lockup. The curl client will block trying to send more data while the application blocks trying to read. The point where th size of the POST body is printed to stderr is then never reached.
A slight modification of the code makes it use TestServlet2 with a doPost that processes the input expecting a ZIP-formatted body by reading and discarding entries and printing the name:size of each entry to stderr. Posting a sufficiently large ZIP file to it shows that initial entries are processed corrrectly then it locks up the same way as with TestServlet1.
Small POST requests seem to work without issues. GET requests seem to work fine also and our application ported from Jetty 11 to Jetty 12 works mostly fine except for large POST requests.
How to reproduce?
See the above description. I am sorry that this is Scala code instead of Java. I currently have no Java development environment setup.
Compile/runtime dependencies specified in build.sbt, some of which redundant for the test code
Scala code
The text was updated successfully, but these errors were encountered: