Bug 55799 - [websocket] Stability issues when concurrently sending large messages
[websocket] Stability issues when concurrently sending large messages
Status: RESOLVED FIXED
Product: Tomcat 8
Classification: Unclassified
Component: WebSocket
trunk
PC All
: P2 normal (vote)
: ----
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2013-11-20 00:01 UTC by Konstantin Preißer
Modified: 2013-11-29 02:01 UTC (History)
0 users



Attachments
Test case (modifications to the Chat example) (3.14 KB, patch)
2013-11-20 00:01 UTC, Konstantin Preißer
Details | Diff
Screenshot of FF getting a raw websocket respone (1) (49.95 KB, image/png)
2013-11-20 00:02 UTC, Konstantin Preißer
Details
Screenshot of FF getting a raw websocket respone (2) (49.87 KB, image/png)
2013-11-20 00:03 UTC, Konstantin Preißer
Details
Updated Test case (modifications to the Chat example) (2.19 KB, patch)
2013-11-20 14:48 UTC, Konstantin Preißer
Details | Diff
Sample project to replicate regression (26.15 KB, application/zip)
2013-11-26 23:38 UTC, Nick Williams
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Preißer 2013-11-20 00:01:34 UTC
Created attachment 31055 [details]
Test case (modifications to the Chat example)

Hi,

a thread on the Users List [1] described that problems can occur when sending large messages over a WebSocket connection using getBasicRemote().sendText(String).

The ChatAnnotation class does not synchronize when using this method, which means that multiple threads could call RemoteEndpoint.Basic#sendText() concurrently.

The JavaDoc of RemoteEndpoint.Basic says:

"If the websocket connection underlying this RemoteEndpoint is busy sending a message when a call is made to send another one, for example if two threads attempt to call a send method concurrently, or if a developer attempts to send a new message while in the middle of sending an existing one, the send method called while the connection is already busy may throw an IllegalStateException."

(I thought I had read earlier that the implementation should synchronize calls to methods of RemoteEndpoint.Basic instead of throwing an ISE, but maybe that has changed).


When sending large Messages over Websocket using RemoteEndpoint.Basic from different threads without or with synchronization, some problems happen like:
a) The WebSocket connection is suddenly closed (I guess the browser
   actually aborts the connections due to data corruption or Timeout errors,
   but I have not examined the raw data sent over TCP)
b) Various Exceptions occur (see below)
c) Sometimes when I open the chat.xhtml example in my browser, it shows what
   seems to be a raw WebSocket response instead of the .xhtml file (see
   added screenshots)

These issues also happen after synchronizing calls to RemoteEndpoint.Basic#sendText(), but are then harder to reproduce.



To reproduce: 
1) Checkout Tomcat 8 trunk (r1543467) and apply the attached patch. It applies some modifications to the Chat Websocket Example, so that the Javascript sends messages in a regular interval (50 ms), and the ChatAnnotation modifies the message to be 256 times as large as the original message, and sends it back using session.getBasicRemote()#sendText(msg). 

2) Build Tomcat and run it on a Windows machine (I used Windows 8.1 x64, Java 1.7.0_45 x64), using the NIO HTTP connector (default configuration).

3) Open Firefox and IE 11. With both browsers, open the Chat example (http://localhost:8080/examples/websocket/chat.xhtml).

4) Repeat the following actions in a regular interval:
   a) Wait several seconds (it might be that Tomcat already closes one of
      the two WebSocket connections in that time).
   b) On one of the browsers (e.g. IE), press F5 several times.

5) After some time, you can see that in one of the browsers, the WebSocket connection is suddenly closed. Tomcat will show one or more of the following exceptions (I think the IOException and ClosedChannelException are expected if the browser aborts the connection):


19-Nov-2013 23:18:39.809 SEVERE [http-nio-8080-ClientPoller-0] org.apache.tomcat.util.net.NioEndpoint.processSocket Error allocating socket processor
 java.lang.NullPointerException
	at org.apache.tomcat.util.net.NioEndpoint.processSocket(NioEndpoint.java:624)
	at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1165)
	at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1122)
	at java.lang.Thread.run(Thread.java:744)


19-Nov-2013 23:32:16.601 SEVERE [http-nio-8080-exec-3] websocket.chat.ChatAnnotation.onError Chat Error: java.nio.channels.ClosedChannelException
 java.nio.channels.ClosedChannelException
	at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:252)
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:295)
	at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:136)
	at org.apache.coyote.http11.upgrade.NioServletInputStream.fillReadBuffer(NioServletInputStream.java:136)
	at org.apache.coyote.http11.upgrade.NioServletInputStream.doIsReady(NioServletInputStream.java:49)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.isReady(AbstractServletInputStream.java:62)
	at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:44)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:192)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:180)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)


19-Nov-2013 23:32:19.658 SEVERE [http-nio-8080-exec-2] websocket.chat.ChatAnnotation.onError Chat Error: java.lang.IllegalArgumentException: java.lang.reflect.InvocationTargetException
 java.lang.IllegalArgumentException: java.lang.reflect.InvocationTargetException
	at org.apache.tomcat.websocket.pojo.PojoMessageHandlerWholeBase.onMessage(PojoMessageHandlerWholeBase.java:82)
	at org.apache.tomcat.websocket.WsFrameBase.sendMessageText(WsFrameBase.java:369)
	at org.apache.tomcat.websocket.WsFrameBase.processDataText(WsFrameBase.java:468)
	at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:272)
	at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:116)
	at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:55)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:192)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:180)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.reflect.InvocationTargetException
	at sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.apache.tomcat.websocket.pojo.PojoMessageHandlerWholeBase.onMessage(PojoMessageHandlerWholeBase.java:80)
	... 15 more
Caused by: java.nio.charset.CoderMalfunctionError: java.nio.BufferOverflowException
	at java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:565)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.write(WsRemoteEndpointImplBase.java:624)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPartialString(WsRemoteEndpointImplBase.java:197)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendString(WsRemoteEndpointImplBase.java:154)
	at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:37)
	at websocket.chat.ChatAnnotation.broadcast(ChatAnnotation.java:96)
	at websocket.chat.ChatAnnotation.incoming(ChatAnnotation.java:83)
	... 19 more
Caused by: java.nio.BufferOverflowException
	at java.nio.Buffer.nextPutIndex(Buffer.java:513)
	at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:163)
	at org.apache.tomcat.util.buf.Utf8Encoder.encodeNotHasArray(Utf8Encoder.java:177)
	at org.apache.tomcat.util.buf.Utf8Encoder.encodeLoop(Utf8Encoder.java:40)
	at java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:561)
	... 25 more


19-Nov-2013 23:32:23.353 SEVERE [http-nio-8080-exec-10] websocket.chat.ChatAnnotation.onError Chat Error: java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
 java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
	at sun.nio.ch.SocketDispatcher.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
	at sun.nio.ch.IOUtil.read(IOUtil.java:197)
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379)
	at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:136)
	at org.apache.coyote.http11.upgrade.NioServletInputStream.fillReadBuffer(NioServletInputStream.java:136)
	at org.apache.coyote.http11.upgrade.NioServletInputStream.doRead(NioServletInputStream.java:80)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.read(AbstractServletInputStream.java:124)
	at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:46)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:192)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:180)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)


If you try to press F5, then it might be that the Websocket connection is closed as soon as it was opened, or that the browser doesn't get a response for the request to chat.xhtml.



Now, add synchronization by modifying ChatAnnotation's broadcast() method:

    private static void broadcast(String msg) {
        for (ChatAnnotation client : connections) {
            synchronized (client) {
                try {
                    client.session.getBasicRemote().sendText(msg);
                } catch (Exception e) {
    
                }
            }
        }
    }

and repeat the above steps.

Now, if you open chat.xhtml with both IE and Firefox and do nothing, the WebSocket connection will not be closed. Even if you start to repeatedly press F5, most of the time everything will appear normal (besides getting IOExceptions and ClosedChannelExceptions).

However, after I tried this several minutes, I still got the problems that the WebSocket connections are closed just after opening it (or after some time), or that the browser didn't get a response to its HTTP request, or that the browser got a raw WebSocket reply instead of the XHTML page reply (see added screenshots).

I also got these exceptions:

20-Nov-2013 00:18:20.037 SEVERE [http-nio-8080-exec-9] websocket.chat.ChatAnnotation.onError Chat Error: java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
 java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:226)
	at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:476)
	at org.apache.tomcat.websocket.WsSession.onClose(WsSession.java:439)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.close(WsHttpUpgradeHandler.java:172)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.access$200(WsHttpUpgradeHandler.java:45)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:194)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:180)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)
Caused by: java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
	at org.apache.tomcat.websocket.FutureToSendHandler.get(FutureToSendHandler.java:102)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:222)
	... 14 more
Caused by: java.io.IOException: Key must be cancelled
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:83)
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:60)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:118)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:85)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:94)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:362)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:259)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:217)
	... 14 more


20-Nov-2013 00:32:53.483 SEVERE [http-nio-8080-exec-3] org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun 
 java.lang.NullPointerException
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:593)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)


20-Nov-2013 00:35:19.333 SEVERE [http-nio-8080-exec-15] org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.destroy Failed to close WebConnection while destroying the WebSocket HttpUpgradeHandler
 java.lang.NullPointerException
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.destroy(WsHttpUpgradeHandler.java:143)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:715)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)


20-Nov-2013 00:35:19.327 SEVERE [http-nio-8080-exec-15] org.apache.coyote.http11.AbstractHttp11Processor.process Error processing request
 java.lang.IllegalArgumentException
	at java.nio.Buffer.position(Buffer.java:236)
	at sun.nio.ch.IOUtil.write(IOUtil.java:68)
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:487)
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:123)
	at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101)
	at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:174)
	at org.apache.coyote.http11.InternalNioOutputBuffer.writeToSocket(InternalNioOutputBuffer.java:140)
	at org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:198)
	at org.apache.coyote.http11.InternalNioOutputBuffer.commit(InternalNioOutputBuffer.java:178)
	at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:739)
	at org.apache.coyote.Response.action(Response.java:180)
	at org.apache.coyote.Response.sendHeaders(Response.java:368)
	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:335)
	at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:290)
	at org.apache.catalina.connector.Response.finishResponse(Response.java:411)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:560)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1015)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:642)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)




[1] http://markmail.org/message/ee3jch4zj2orltzs
Comment 1 Konstantin Preißer 2013-11-20 00:02:40 UTC
Created attachment 31056 [details]
Screenshot of FF getting a raw websocket respone (1)
Comment 2 Konstantin Preißer 2013-11-20 00:03:03 UTC
Created attachment 31057 [details]
Screenshot of FF getting a raw websocket respone (2)
Comment 3 Konstantin Preißer 2013-11-20 00:22:31 UTC
Note: When using Google Chrome and when the WebSocket connection fails, Chrome reports one of the following errors in the console:

WebSocket connection to 'ws://localhost:8080/examples/websocket/chat' failed: Status line contains embedded null

WebSocket connection to 'ws://localhost:8080/examples/websocket/chat' failed: Received unexpected continuation frame.
Comment 4 Mark Thomas 2013-11-20 10:20:07 UTC
I can see one problem immediately. While the code does check for concurrent messages (which will trigger an IllegalStateException) text messages are converted to bytes before that check in a single buffer. Therefore, multiple threads could access that buffer and that will cause corruption. I'll take a look.
Comment 5 Mark Thomas 2013-11-20 14:04:38 UTC
I've hopefully fixed this in trunk. If you can provide some feedback on the fix that would be great.

I'm leaving this open as I have a little clean-up still to do in trunk for this fix and I also want to back-port the changes to 7.0.x.
Comment 6 Konstantin Preißer 2013-11-20 14:48:16 UTC
Created attachment 31060 [details]
Updated Test case (modifications to the Chat example)

Hi Mark,

I updated my working copy of Tomcat 8 trunk to r1543817 and have the changes applied from the attached patch. It modifies the Chat example in the same way as the previous test case (and it changes the catch (IOException e) to catch (Exception e) to also catch ISE, and do not remove a client in this catch block - instead wait for the onClose method to be called).

Unfortunately, even with the fix and the added synchronized() block in the Chat's broadcast() method, I still see the same problems as before (WebSocket connection is closed soon after it is opened, Chrome displays "Unexpected continuation frame" error, browser receives raw websocket response instead of the requested chat.xhtml file).

I also got following exceptions (Note: One of the NPEs is probably the same that I once observed with the DrawBoard example and the NIO connector when repeatedly pressing F5):


Exception in thread "WebSocketServer-localhost-/examples-1" java.lang.IllegalStateException: Unexpected state. Please report a bug. Message will not be sent because the WebSocket session is currently sending another message
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:272)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.write(WsRemoteEndpointImplBase.java:643)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.onResult(WsRemoteEndpointImplBase.java:653)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.endMessage(WsRemoteEndpointImplBase.java:305)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$EndMessageHandler.onResult(WsRemoteEndpointImplBase.java:453)
        at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer$OnResultRunnable.run(WsRemoteEndpointImplServer.java:234)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)


20-Nov-2013 15:25:04.759 SEVERE [http-nio-8080-exec-4] websocket.chat.ChatAnnotation.onError Chat Error: java.lang.NullPointerException
 java.lang.NullPointerException
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.onWritePossible(AbstractServletOutputStream.java:134)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:97)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1551)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)


20-Nov-2013 15:30:49.345 SEVERE [http-nio-8080-ClientPoller-1] org.apache.tomcat.util.net.NioEndpoint.processSocket Error allocating socket processor
 java.lang.NullPointerException
	at org.apache.tomcat.util.net.NioEndpoint.processSocket(NioEndpoint.java:624)
	at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1165)
	at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1122)
	at java.lang.Thread.run(Thread.java:744)


20-Nov-2013 15:32:33.070 SEVERE [http-nio-8080-exec-5] org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun 
 java.lang.NullPointerException
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:593)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)


20-Nov-2013 15:32:53.378 SEVERE [http-nio-8080-exec-23] org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process Error reading request, ignored
 java.lang.IllegalStateException: Unexpected state. Please report a bug. Message will not be sent because the WebSocket session is currently sending another message
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:272)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.write(WsRemoteEndpointImplBase.java:643)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.onResult(WsRemoteEndpointImplBase.java:653)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.endMessage(WsRemoteEndpointImplBase.java:305)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$EndMessageHandler.onResult(WsRemoteEndpointImplBase.java:453)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.clearHandler(WsRemoteEndpointImplServer.java:206)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:102)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsWriteListener.onWritePossible(WsHttpUpgradeHandler.java:238)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.onWritePossible(AbstractServletOutputStream.java:167)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:97)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1551)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)


20-Nov-2013 15:24:55.951 SEVERE [http-nio-8080-exec-9] websocket.chat.ChatAnnotation.onError Chat Error: java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
 java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:245)
	at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:476)
	at org.apache.tomcat.websocket.WsSession.onClose(WsSession.java:439)
	at org.apache.tomcat.websocket.WsFrameBase.processDataControl(WsFrameBase.java:316)
	at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:270)
	at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:116)
	at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:55)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:192)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:180)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)
Caused by: java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
	at org.apache.tomcat.websocket.FutureToSendHandler.get(FutureToSendHandler.java:102)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:241)
	... 16 more
Caused by: java.io.IOException: Key must be cancelled
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:83)
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:60)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:118)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:85)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:94)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:378)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:279)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:236)
	... 16 more

	
[Probably expected, when the browser aborts the connection:]
20-Nov-2013 15:25:24.777 SEVERE [http-nio-8080-exec-8] websocket.chat.ChatAnnotation.onError Chat Error: java.io.IOException: java.util.concurrent.ExecutionException: java.nio.channels.ClosedChannelException
 java.io.IOException: java.util.concurrent.ExecutionException: java.nio.channels.ClosedChannelException
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:245)
	at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:476)
	at org.apache.tomcat.websocket.WsSession.onClose(WsSession.java:439)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.close(WsHttpUpgradeHandler.java:172)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.access$200(WsHttpUpgradeHandler.java:45)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:194)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:180)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1555)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)
Caused by: java.util.concurrent.ExecutionException: java.nio.channels.ClosedChannelException
	at org.apache.tomcat.websocket.FutureToSendHandler.get(FutureToSendHandler.java:102)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:241)
	... 14 more
Caused by: java.nio.channels.ClosedChannelException
	at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java:265)
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:474)
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:123)
	at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:185)
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:93)
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:60)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:118)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:85)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:94)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:378)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:279)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:236)
	... 14 more
Comment 7 Mark Thomas 2013-11-20 20:58:49 UTC
I'm not seeing the errors you are seeing but I did spot a possible failure mode which I have now fixed. Could you re-test 8.0.x please.
Comment 8 Konstantin Preißer 2013-11-20 21:47:22 UTC
Hi Mark,

(In reply to Mark Thomas from comment #7)
> I'm not seeing the errors you are seeing but I did spot a possible failure
> mode which I have now fixed. Could you re-test 8.0.x please.

Thanks a lot. I updated to r1543948 and cannot reproduce the main problems any more (like websocket connection suddenly closes, wrong response sent to the browser). I think it is fixed now.

I also don't get NPEs or IllegalArgumentExceptions any more. I still do see IOExceptions ("Software caused connection abort" / "Key must be cancelled") and ClosedChannelExceptions reported through the ChatAnnotation's onError method, but these are probably expected due to the browser aborting the connection when repeatedly pressing F5.

I also still see the following exception:

Exception in thread "WebSocketServer-localhost-/examples-14"
java.lang.IllegalStateException: Message will not be sent because the WebSocket session has been closed
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:306)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:273)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.write(WsRemoteEndpointImplBase.java:637)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.onResult(WsRemoteEndpointImplBase.java:649)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.endMessage(WsRemoteEndpointImplBase.java:299)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$EndMessageHandler.onResult(WsRemoteEndpointImplBase.java:447)
        at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer$OnResultRunnable.run(WsRemoteEndpointImplServer.java:234)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
Comment 9 Konstantin Preißer 2013-11-20 21:58:02 UTC
(In reply to Konstantin Preißer from comment #8)
> I also still see the following exception:

Actually I meant the following exception here (but the other one also occurs):

Exception in thread "WebSocketServer-localhost-/examples-1" java.lang.IllegalStateException: Unexpected state. Please report a bug. Message will not be sent because the WebSocket session is currently sending another message
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:266)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.write(WsRemoteEndpointImplBase.java:637)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$TextMessageSendHandler.onResult(WsRemoteEndpointImplBase.java:649)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.endMessage(WsRemoteEndpointImplBase.java:299)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$EndMessageHandler.onResult(WsRemoteEndpointImplBase.java:447)
        at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer$OnResultRunnable.run(WsRemoteEndpointImplServer.java:234)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
Comment 10 Konstantin Preißer 2013-11-20 22:18:02 UTC
(In reply to Konstantin Preißer from comment #8)
> Thanks a lot. I updated to r1543948 and cannot reproduce the main problems
> any more (like websocket connection suddenly closes, wrong response sent to
> the browser). I think it is fixed now.

After some additional testing, the problem that the browser could not establish a WebSocket connection / Websocket connection is closed a few seconds after opening it happened again on Google Chrome, the console displayed the following:

WebSocket connection to 'ws://localhost:8080/examples/websocket/chat' failed: Received new data frame but previous continuous frame is unfinished.
Comment 11 Mark Thomas 2013-11-20 23:51:43 UTC
OK. Getting better but maybe not quite there yet. Because WebSocket has the potential for multiple threads to be working with a socket concurrently (one read, one write) there is a world of opportunity for weird and wonderful failure modes. It is possible that that is what we are seeing here but I'd like to at least understand each class of exceptions you are seeing.

The IOExceptions and ClosedChannelExceptions are expected when the client drops the connection. I'm not worried about these.

The IllegalStateException (closed) might be OK but I need to confirm.

The IllegalStateException (report a bug) shouldn't happen so I want to look at this some more.

The "Received new data frame but previous continuous frame is unfinished." definitely shouldn't happen. Need to look into that as well.
Comment 12 Mark Thomas 2013-11-21 09:38:21 UTC
(In reply to Mark Thomas from comment #11)
> The IllegalStateException (closed) might be OK but I need to confirm.

It is OK but could be handled better so I have improved the handling of this.

> The IllegalStateException (report a bug) shouldn't happen so I want to look
> at this some more.

The logic was wrong here so it has been fixed.

> The "Received new data frame but previous continuous frame is unfinished."
> definitely shouldn't happen. Need to look into that as well.

I suspect that these were a result of the logic errors.

8.0.x has been updated. As I still can't reproduce this I'd again appreciate your help with testing.
Comment 13 Konstantin Preißer 2013-11-21 15:09:09 UTC
Hi Mark,

(In reply to Mark Thomas from comment #12)
> 8.0.x has been updated. As I still can't reproduce this I'd again appreciate
> your help with testing.

I updated to r1544165 and I'm now unable to reproduce the Exceptions (besides the expected IOException) and the frame error that Google Chrome's console had shown, so I think it is now fixed. Thanks!

(The only problem I got was that it took several minutes for Tomcat to shutdown after testing - it did not close the Websocket Connections and even after closing all browsers it took some minutes for Tomcat to complete shutdown.)
Comment 14 Mark Thomas 2013-11-21 15:32:55 UTC
Thanks for the testing.

The slow shutdown could be caused by not correctly handling an IOException. That is something to follow-up in a separate BZ issue.
Comment 15 Konstantin Kolinko 2013-11-26 04:51:05 UTC
REOPENING, there is a regression

See thread on users@,
"IllegalStateException sending WebSocket message that worked a few months ago"
http://tomcat.markmail.org/thread/75uisvwve2l2u3n2

Apparently using an OutputStream obtained via WsRemoteEndpointImplBase.getSendStream() is broken.


There is a test case for a writer, TestWsRemoteEndpoint.doTestWriter(..). It seems that there is no test case for a stream.

There is a small difference in implementation between doWrite() methods of WsRemoteEndpointImplBase$WsWriter and WsRemoteEndpointImplBase$WsOutputStream:

The writer calls a package-visible method that does not perform a state check.
The stream calls a public method that performs a state check and fails.
Comment 16 Mark Thomas 2013-11-26 11:32:13 UTC
I've fixed the regression and added a test case for Stream messages to trunk and 7.0.x.
Comment 17 Nick Williams 2013-11-26 23:38:12 UTC
Created attachment 31078 [details]
Sample project to replicate regression

Something still isn't quite right. I've attached a sample project. It's silly-looking, I know, but it's simple and it demonstrates the problem reliably every time. Steps:

1. Compile it and deploy to /cluster.
2. Go to http://localhost:8080/cluster/clusterNode1. The browser should display "OK" and there should be some diagnostic output in stdout.
3. Go to http://localhost:8080/cluster/clusterNode2. The browser should display "OK" and there should be a lot more diagnostic output in stdout.

-- Step 3 is where it failed two days ok. You never saw "OK" and the diagnostic output. You just got the exception in the browser. After Mark's changes last night / this morning, step 3 succeeds.

4. Go back to http://localhost:8080/cluster/clusterNode1. The exception is back.
5. Go back to http://localhost:8080/cluster/clusterNode2. The exception is back there, tee.
Comment 18 Mark Thomas 2013-11-28 14:56:23 UTC
Should be fixed now. Test case appears to work. (No errors reported)
Comment 19 Nick Williams 2013-11-29 02:01:59 UTC
Confirmed. Looks like it is working now. Thanks!