Input stream is corrupted when reading via a spawned thread with jetty thread in suspended state.

More info from the list:

Here's a stack trace:

Exception in thread "pool-1-thread-1" java.lang.RuntimeException: java.io.IOException: bad chunk char: 61
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:65)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:637)
Caused by: java.io.IOException: bad chunk char: 61
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:694)
at org.mortbay.jetty.HttpParser$Input.blockForContent(HttpParser.java:1038)
at org.mortbay.jetty.HttpParser$Input.read(HttpParser.java:999)
at java.io.InputStream.read(InputStream.java:85)
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:59)

With enough runs, you'll also see equivalent exceptions with different characters causing the chunking failure instead of '&' ('1', 'p', etc.). These (and variants) may also show up:

java.io.IOException: FULL
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:266)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:205)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:380)
at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:395)
at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:488)

Or

java.lang.IllegalArgumentException
at java.nio.Buffer.position(Buffer.java:218)
at org.mortbay.io.nio.ChannelEndPoint.fill(ChannelEndPoint.java:121)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:282)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:205)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:380)
at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:395)
at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:488)

For the last one, the issue is that NIOBuffer is trying to move the underlying ByteBuffer to a negative position.

And then with a little luck, you'll get this kind of failure:

Malformed hunk from request 1177: pp676=0123456789
Malformed hunk from request 1002: p1001=0123456789490=0123456789
Malformed hunk from request 1011: p1010=012345678956789

I've posted a minimal test case here:

http://mult.ifario.us/files/jetty-bug.tbz2

To run it:

mvn -Dmaven.test.skip jetty:run-exploded

And then to use Commons HttpClient's client:

mvn -Dtest=C* test

or to use HttpComponents' client:

mvn -Dtest=H* test

until you get something interesting. On my development box, things usually blow up in the 1400-1600 range, but it's possible that the test run will complete without an issue.

From the mailing list:

Hi, Jetty folk –

I'm seeing an odd issue with Jetty 6.1.x with continuations and select-style NIO when a client is sending a chunked request that consists of a few chunks. The intended use case is that request processing occurs in the background, so the implementation forks a thread to consume the InputStream from the request and then suspend() is called on the continuation.

The issue is that the request InputStream gets corrupted when suspend() is called. Anyone experienced something similar?

Thanks in advance.

– Paul

===========================================================================

Paul,

I am not sure you can manage continuation in a separated thread as the basic of continuation.suspend is to
throw an exception to roughly stop the end-point thread. Jesse to confirm that point.

Fred

===========================================================================

Paul,

Just to clarify - you're spawning a thread to read the input stream, and then
calling suspend() from the original request-processing thread, yes?

If so, you should be able to use a forked thread to read the IO stream.

Have you got more precise information on what is going wrong, such as a
stack trace? Also, if you had a little test rig that demonstrated the problem
that would be helpful.

cheers
Jan

===========================================================================

Hi, Jan –

> Just to clarify - you're spawning a thread to read the input stream, and then
> calling suspend() from the original request-processing thread, yes?

That's correct, with the additional caveat that the issue only occurs:

1) If the client is using chunked transfer encoding.
2) If it's not the first request sent to the container.
3) If the request splits into several chunks; very small or very large requests seem OK.

> If so, you should be able to use a forked thread to read the IO stream.

Cool! I was hoping that it was a supported use case. The documentation for the select-based endpoint makes it clear that the request body won't be available for the second pass but doesn't say anything about the interim.

> Have you got more precise information on what is going wrong, such as a
> stack trace? Also, if you had a little test rig that demonstrated the problem
> that would be helpful.

I'll see if I can cook up a little test rig.

I spent a good amount of time debugging the issue (to eliminate CXF, internal code, etc.), and here's a summary. The forked thread contains an StAX parser, and I plumbed a CountDownLatch into the system so that I could trigger the continuation's suspend() after some amount of processing on the web service's background thread. I watched the text look-ahead that's part of the HttpParser within the servlet request. Up until the point where the continuation is triggered, it contains the expected "<soap:envelope>...", but once I release the latch and the continuation is triggered (but before the parser has started reading) the buffer jumps ahead and the buffer contains something like "oo>bar</foo>..." from the middle of the message.

I'll file a Jira once I can get Ben to reset my password. Codehaus Jira isn't emailing me for some reason.

– Paul

===========================================================================

Hi, Jan –

On May 26, 2008, at 2:41 PM, Jan Bartel wrote:
> Have you got more precise information on what is going wrong, such as a
> stack trace? Also, if you had a little test rig that demonstrated the problem
> that would be helpful.

Here's a stack trace:

Exception in thread "pool-1-thread-1" java.lang.RuntimeException: java.io.IOException: bad chunk char: 61
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:65)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:637)
Caused by: java.io.IOException: bad chunk char: 61
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:694)
at org.mortbay.jetty.HttpParser$Input.blockForContent(HttpParser.java:1038)
at org.mortbay.jetty.HttpParser$Input.read(HttpParser.java:999)
at java.io.InputStream.read(InputStream.java:85)
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:59)

With enough runs, you'll also see equivalent exceptions with different characters causing the chunking failure instead of '&' ('1', 'p', etc.). These (and variants) may also show up:

java.io.IOException: FULL
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:266)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:205)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:380)
at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:395)
at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:488)

Or

java.lang.IllegalArgumentException
at java.nio.Buffer.position(Buffer.java:218)
at org.mortbay.io.nio.ChannelEndPoint.fill(ChannelEndPoint.java:121)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:282)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:205)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:380)
at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:395)
at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:488)

For the last one, the issue is that NIOBuffer is trying to move the underlying ByteBuffer to a negative position.

And then with a little luck, you'll get this kind of failure:

Malformed hunk from request 1177: pp676=0123456789
Malformed hunk from request 1002: p1001=0123456789490=0123456789
Malformed hunk from request 1011: p1010=012345678956789

I've posted a minimal test case here:

http://mult.ifario.us/files/jetty-bug.tbz2

To run it:

mvn -Dmaven.test.skip jetty:run-exploded

And then to use Commons HttpClient's client:

mvn -Dtest=C* test

or to use HttpComponents' client:

mvn -Dtest=H* test

until you get something interesting. On my development box, things usually blow up in the 1400-1600 range, but it's possible that the test run will complete without an issue.

Cheers.

– Paul

===========================================================================

Paul,

FYI, I've raised a Jetty issue for this:

http://jira.codehaus.org/browse/JETTY-586

cheers
Jan

===========================================================================

Hi Paul,

What OS did you use with the test? I was not able to replicate this on a windows xp box.

Cheers

===========================================================================

Hi, David –

I ran the tests on Mac OS X (10.5.2, Intel, Java 6), but the original issue occurred on Mac OS X, Linux, and on Windows. (In some cases, Jetty was running "embedded" in Maven but in others it was running bare.) You may have to run several runs to get the issue to occur with the little harness I provided. Also, the machines producing the issue are relatively modern (multi-core, fast), and it's possible that it might not occur on older hardware.

Best.

– Paul

===========================================================================

Hi Paul,

I'm beginning to think this is an java1.6 related issue. Tried this many times on windows xp and fc7(java 1.5), and the test completed without errors.
Can you try testing against java 1.5 and see if you're still getting the error?

Thanks

===========================================================================

Hi, David –

I just tried with Java5 on my Mac, and the issue occurs after a few repetitions of

mvn -Dtest=C* test

The trace in this case is the same as some of them on Java6:

2008-05-29 21:28:40.635::WARN: handle failed
java.lang.IndexOutOfBoundsException: -6630
at java.nio.DirectByteBuffer.get(DirectByteBuffer.java:209)
at org.mortbay.io.nio.NIOBuffer.peek(NIOBuffer.java:86)
at org.mortbay.io.AbstractBuffer.peek(AbstractBuffer.java:306)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:656)

FWIW, I'm not able to provoke the issue by running the tests in sequence (mvn test), so try repeated runs of either test with a single client implementation.

– Paul

Jesse,

As the owner of a mac, could you do the suggested tests and see if you can reproduce the failure? We haven't been able to reproduce on linux or various windows flavours.

thanks!
Jan

hm...

yes, the scenario above does manifest on my mac with both java5 and java6..

java5 kicked out this exception server side:

Exception in thread "pool-1-thread-7" java.lang.RuntimeException: java.io.IOException: bad chunk char: 61
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:55)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:613)
Caused by: java.io.IOException: bad chunk char: 61
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:694)
at org.mortbay.jetty.HttpParser$Input.blockForContent(HttpParser.java:1038)
at org.mortbay.jetty.HttpParser$Input.read(HttpParser.java:999)
at java.io.InputStream.read(InputStream.java:89)
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:49)

against 6.1.12.rc2 with java6 this was the server side exception:

Exception in thread "pool-1-thread-4" java.lang.RuntimeException: java.io.IOException: bad chunk char: 61
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:55)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:637)
Caused by: java.io.IOException: bad chunk char: 61
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:708)
at org.mortbay.jetty.HttpParser$Input.blockForContent(HttpParser.java:1058)
at org.mortbay.jetty.HttpParser$Input.read(HttpParser.java:1019)
at java.io.InputStream.read(InputStream.java:85)
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:49)
... 3 more

I updated this to the 7.0-SNAPSHOT and out pops this exception which seems to be digging in a bit deeper:

[POST /test/]@679408063 HANDLING,initial,timeout
Exception in thread "pool-1-thread-14" java.lang.IndexOutOfBoundsException
at java.nio.Buffer.checkIndex(Buffer.java:514)
at java.nio.DirectByteBuffer.get(DirectByteBuffer.java:233)
at org.mortbay.io.nio.NIOBuffer.peek(NIOBuffer.java:94)
at org.mortbay.io.AbstractBuffer.peek(AbstractBuffer.java:308)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:672)
at org.mortbay.jetty.HttpParser$Input.blockForContent(HttpParser.java:1060)
at org.mortbay.jetty.HttpParser$Input.read(HttpParser.java:1021)
at java.io.InputStream.read(InputStream.java:85)
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:49)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:637)

http://www.nabble.com/JDK-1.5,-1.6-and-FreeBSD-td18890186.html

that looks to be a somewhat related issue, someone having issues uploading content through jetty and having activemq process it...

I just retried the test-case on windows+java1.5+jetty-6.1.10, I got the ff:

Exception in thread "pool-1-thread-3" java.lang.RuntimeException: java.io.IOExce
ption: bad chunk char: 61
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:55)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExec
utor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor
.java:675)
at java.lang.Thread.run(Thread.java:595)
Caused by: java.io.IOException: bad chunk char: 61
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:694)
at org.mortbay.jetty.HttpParser$Input.blockForContent(HttpParser.java:10
38)
at org.mortbay.jetty.HttpParser$Input.read(HttpParser.java:999)
at java.io.InputStream.read(InputStream.java:89)
at us.ifario.mult.EchoServlet$Printer.run(EchoServlet.java:49)
... 3 more
2009-01-05 16:38:09.691::WARN: handle failed
java.io.IOException: bad chunk char: 38
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:694)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:205)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:380)
at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.ja
va:395)
at org.mortbay.jetty.nio.SelectChannelConnector$RetryContinuation.run(Se
lectChannelConnector.java:506)
at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:488)

windows+java1.5+jetty-6.1.14 as well.

Ported to jetty-7 continuations, with problem demonstrated on last chunk of a series of TCP packets where we send the CRLF at the end of the packet, but the beginning of the next packet does not contain the size of the chunk.

Greg,
I ported the app to jetty-7 continuations. It often runs absolutely fine. I was lucky enough to get it to fail whilst running wireshark and grabbed a dump.

It appears that the response is split over a few tcp packets and is normally fine. However on the failing reponse, the 2nd to last tcp packet contains the CRLF delimiter for the chunk, but the next (last) packet does not contain the byte count for the next chunk.

To run this, you need 2 windows. In one window do: "mvn jetty:run". In the other do "mvn -Dtest=CommonsHttpClientPostTest test".
Please take a look into this one.

Jan

jetty_bug-7.0.tgz appears to be corrupted. can you attach again.

Trying again.

Simone,
can you try to reproduce this one? The wireshark trace that jan got definitely shows an error, but for 3 days I've been trying to reproduce, but all is OK for me.

Can you have a try.... if it is a bug, good to get it fixed before 7.1.1 - so we have a few weeks.

Jan, please reattach the tgz, it is still broken for me.

Simone,

The attached jetty_bug-7.0.tgz is gzip'd twice.
Unpack it like this ...

$ gzip -dc jetty_bug-7.0.tgz | gzip -dc | tar -xv

This has not be reproduced and a lot of changes have happened since this was reported.

If this is still a problem, please reproduce on 7.3.x and reopen this issue.