Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [jetty-users] "java.io.IOException: Cannot append to finished buffer" in SimpleTextMessage
hi,

Reviving an old thread here. We continue to see the same failures periodically (e.g. 2 of 10 times) on the CI server only, never locally. 

In response to Joakim's comment below that "an extra frame arrived after the supposed last frame of the last message" based on actual logging I'm wondering if there couldn't be a potential concurrency issue?

See for example these two log statements that correspond to two WebSocket messages in the same session (the only session in the test) processed at nearly (and possibly) the same time in two different threads:

06:43:13,160 [WebSocketClient@1545468091-533] - Processing SockJS open frame in WebSocketClientSockJsSession[id='b61c4e070bc4e81c83801f2fbe6a27e2, url="" href="http://localhost:53793/test">http://localhost:53793/test]
...
06:43:13,161 [WebSocketClient@1545468091-536] - Unhandled Error (closing connection)
java.io.IOException: Cannot append to finished buffer
        at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.appendFrame(SimpleTextMessage.java:47)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:60)
        at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextFrame(JettyAnnotatedEventDriver.java:201)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:160)
        at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:309)
        at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:214)
        at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220)
        at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:258)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:613)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:468)
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:626)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:546)
        at java.lang.Thread.run(Thread.java:745)

One another example with a different error message but in the same part of the code:

17:33:30,200 [WebSocketClient@588756412-539] - Processing SockJS open frame in WebSocketClientSockJsSession[id='64344caa5fa655c02bd54982011f31be, url="" href="http://localhost:4113/test">http://localhost:4113/test]
...
17:33:30,201 [WebSocketClient@588756412-538] - Unhandled Error (closing connection)
java.io.IOException: Out of order Continuation frame encountered
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.onContinuationFrame(AbstractEventDriver.java:194)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:165)
        at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:309)
        at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:214)
        at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220)
        at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:258)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:613)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:468)
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:626)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:546)
        at java.lang.Thread.run(Thread.java:745)

Is it possible that under some circumstances on the client side, two incoming WebSocket messages of the same session may not be processed sequentially? The QueuedThreadPool from the stack trace runs in a loop but the log messages are from different threads. 

Any idea what else could possibly lead to the above errors? Also for what it's worth, the same tests parameterized to run with another WebSocket client do not have these failures.

Thanks,
Rossen

On Wed, Jul 2, 2014 at 4:42 PM, Joakim Erdfelt <joakim@xxxxxxxxxxx> wrote:
What features of websocket are you using?
Interested in all features you use, client and server side.
Some features: binary and/or text messages, auto fragmentation, compression extensions, streaming, jsr-356 decoders/encoders, jsr-356 messagehandlers, etc ...


--
Joakim Erdfelt <joakim@xxxxxxxxxxx>
Expert advice, services and support from from the Jetty & CometD experts


On Wed, Jul 2, 2014 at 12:50 PM, Rossen Stoyanchev <rstoyanchev@xxxxxxxxxxxxx> wrote:
Unfortunately I cannot reproduce it reliably. It's hard with concurrency issues like that.

I was hoping the stack trace might lead to some thoughts about what may be going on. Is there anything I could be doing incorrectly to lead to this exception? If not any other theories based on the stack trace? I could try to introduce a delay somewhere even in the Jetty code to get it to occur but could use some help to narrow it down.

Rosen


On Wed, Jul 2, 2014 at 3:27 PM, Joakim Erdfelt <joakim@xxxxxxxxxxx> wrote:
If you have a reproducible testcase we'd like to see it.
The exception is saying that the there was an extra frame (for a text message) that arrived after the supposed last frame of that same message.

--
Joakim Erdfelt <joakim@xxxxxxxxxxx>
Expert advice, services and support from from the Jetty & CometD experts


On Wed, Jul 2, 2014 at 11:40 AM, Rossen Stoyanchev <rstoyanchev@xxxxxxxxxxxxx> wrote:
hi-

I have a simple unit test in which a Jetty WebSocketClient connects to a Jetty server and sends 100 messages in a loop that the server then echoes back. When all messages are received in the client, the test is complete. This runs okay most of the times except occasionally on our CI server there is a client-side failure after 40-50 messages that looks like this:

java.io.IOException: Cannot append to finished buffer
        at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.appendFrame(SimpleTextMessage.java:47)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:60)
        at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextFrame(JettyAnnotatedEventDriver.java:201)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:160)
        at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:302)
        at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:215)
        at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220)
        at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:258)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:602)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:458)
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:534)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536)
        at java.lang.Thread.run(Thread.java:745)

From what I can see all server messages are processed sequentially (always the same Jetty thread) while client side messages are received in different threads. It is possible there is an issue with concurrency in the client?

Rossen



_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users

Back to the top