Bug 57489 - java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
Summary: java.util.concurrent.ExecutionException: java.io.IOException: Key must be can...
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: WebSocket (show other bugs)
Version: 8.0.15
Hardware: PC All
: P2 major with 5 votes (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-01-23 22:54 UTC by wodencafe
Modified: 2015-12-11 12:53 UTC (History)
0 users



Attachments
Test cases for closing websockets (8.79 KB, text/plain)
2015-12-03 16:33 UTC, Barry Coughlan
Details
Websocket client for testing TCP behaviour (3.20 KB, text/plain)
2015-12-03 16:34 UTC, Barry Coughlan
Details

Note You need to log in before you can comment on or make changes to this bug.
Description wodencafe 2015-01-23 22:54:04 UTC
Hello all,

we have been trying to track down the cause of some strange exceptions produced by our application, that are related to the websocket connection somehow being dropped.

This happens in multiple deployments of the application, but this one in particular is on a Windows 8 Machine.

2015-01-22 15:14:09,599 CST WARN  [null] - Duplicate resource 7143de60-6212-4a06-8e2b-ce266c1d9769. Could be caused by a dead connection not detected by your server. Replacing the old one with the fresh one 
2015-01-22 15:14:09,599 CST ERROR [null] - java.io.IOException:  
     at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:276) 
     at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:536) 
     at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:464) 
     at org.apache.tomcat.websocket.WsSession.close(WsSession.java:441) 
     at org.apache.tomcat.websocket.WsSession.close(WsSession.java:435) 
     at org.atmosphere.container.version.JSR356WebSocket.close(JSR356WebSocket.java:142) 
     at org.atmosphere.websocket.WebSocket.close(WebSocket.java:273) 
     at org.atmosphere.cpr.AtmosphereResponse.close(AtmosphereResponse.java:848) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.cancel(AtmosphereResourceImpl.java:779) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.close(AtmosphereResourceImpl.java:855) 
     at com.vaadin.server.communication.AtmospherePushConnection.disconnect(AtmospherePushConnection.java:305) 
     at com.vaadin.server.communication.PushHandler.disconnect(PushHandler.java:430) 
     at com.vaadin.server.communication.PushHandler.onDisconnect(PushHandler.java:330) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.onDisconnect(AtmosphereResourceImpl.java:715) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereResourceImpl.java:618) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereResourceImpl.java:598) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.dirtyClose(AtmosphereResourceImpl.java:864) 
     at org.atmosphere.cpr.DefaultBroadcaster.addAtmosphereResource(DefaultBroadcaster.java:1370) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.suspend(AtmosphereResourceImpl.java:408) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.suspend(AtmosphereResourceImpl.java:324) 
     at com.vaadin.server.communication.PushHandler$2.run(PushHandler.java:131) 
     at com.vaadin.server.communication.PushHandler.callWithUi(PushHandler.java:253) 
     at com.vaadin.server.communication.PushHandler.access$200(PushHandler.java:56) 
     at com.vaadin.server.communication.PushHandler$1.onRequest(PushHandler.java:74) 
     at org.atmosphere.cpr.AsynchronousProcessor.action(AsynchronousProcessor.java:205) 
     at org.atmosphere.cpr.AsynchronousProcessor.suspended(AsynchronousProcessor.java:104) 
     at org.atmosphere.container.Servlet30CometSupport.service(Servlet30CometSupport.java:66) 
     at org.atmosphere.cpr.AtmosphereFramework.doCometSupport(AtmosphereFramework.java:2075) 
     at org.atmosphere.websocket.DefaultWebSocketProcessor.dispatch(DefaultWebSocketProcessor.java:570) 
     at org.atmosphere.websocket.DefaultWebSocketProcessor.open(DefaultWebSocketProcessor.java:215) 
     at org.atmosphere.container.JSR356Endpoint.onOpen(JSR356Endpoint.java:198) 
     at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.init(WsHttpUpgradeHandler.java:138) 
     at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:684) 
     at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222) 
     at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1556) 
     at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1513) 
     at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) 
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) 
     at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) 
     at java.lang.Thread.run(Unknown Source) 
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:269) 
     ... 39 more 
Caused by: java.io.IOException: Key must be cancelled 
     at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:84) 
     at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:61) 
     at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:162) 
     at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:129) 
     at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:99) 
     at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81) 
     at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:444) 
     at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:335) 
     at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:264) 
     ... 39 more 
Caused by: java.util.concurrent.ExecutionException: 
     at org.apache.tomcat.websocket.FutureToSendHandler.get(FutureToSendHandler.java:102) 
     at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:269) 
     at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:536) 
     at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:464) 
     at org.apache.tomcat.websocket.WsSession.close(WsSession.java:441) 
     at org.apache.tomcat.websocket.WsSession.close(WsSession.java:435) 
     at org.atmosphere.container.version.JSR356WebSocket.close(JSR356WebSocket.java:142) 
     at org.atmosphere.websocket.WebSocket.close(WebSocket.java:273) 
     at org.atmosphere.cpr.AtmosphereResponse.close(AtmosphereResponse.java:848) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.cancel(AtmosphereResourceImpl.java:779) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.close(AtmosphereResourceImpl.java:855) 
     at com.vaadin.server.communication.AtmospherePushConnection.disconnect(AtmospherePushConnection.java:305) 
     at com.vaadin.server.communication.PushHandler.disconnect(PushHandler.java:430) 
     at com.vaadin.server.communication.PushHandler.onDisconnect(PushHandler.java:330) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.onDisconnect(AtmosphereResourceImpl.java:715) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereResourceImpl.java:618) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.notifyListeners(AtmosphereResourceImpl.java:598) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.dirtyClose(AtmosphereResourceImpl.java:864) 
     at org.atmosphere.cpr.DefaultBroadcaster.addAtmosphereResource(DefaultBroadcaster.java:1370) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.suspend(AtmosphereResourceImpl.java:408) 
     at org.atmosphere.cpr.AtmosphereResourceImpl.suspend(AtmosphereResourceImpl.java:324) 
     at com.vaadin.server.communication.PushHandler$2.run(PushHandler.java:131) 
     at com.vaadin.server.communication.PushHandler.callWithUi(PushHandler.java:253) 
     at com.vaadin.server.communication.PushHandler.access$200(PushHandler.java:56) 
     at com.vaadin.server.communication.PushHandler$1.onRequest(PushHandler.java:74) 
     at org.atmosphere.cpr.AsynchronousProcessor.action(AsynchronousProcessor.java:205) 
     at org.atmosphere.cpr.AsynchronousProcessor.suspended(AsynchronousProcessor.java:104) 
     at org.atmosphere.container.Servlet30CometSupport.service(Servlet30CometSupport.java:66) 
     at org.atmosphere.cpr.AtmosphereFramework.doCometSupport(AtmosphereFramework.java:2075) 
     at org.atmosphere.websocket.DefaultWebSocketProcessor.dispatch(DefaultWebSocketProcessor.java:570) 
     at org.atmosphere.websocket.DefaultWebSocketProcessor.open(DefaultWebSocketProcessor.java:215) 
     at org.atmosphere.container.JSR356Endpoint.onOpen(JSR356Endpoint.java:198) 
     at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.init(WsHttpUpgradeHandler.java:138) 
     at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:684) 
     at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222) 
     at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1556) 
     at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1513) 
     at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) 
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) 
     at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) 
     at java.lang.Thread.run(Unknown Source) 
Caused by: java.io.IOException: Key must be cancelled 
     at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:84) 
     at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:61) 
     at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:162) 
     at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:129) 
     at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:99) 
     at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81) 
     at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:444) 
     at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:335) 
     at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:264) 
     ... 39 more

Java 8
NIO connector

I reported this to the Atmosphere maintainer, who responded with the following:

jfarcand 	
9:53 AM (6 hours ago)
Hi,
please file a bug in Tomcat, this is clearly an issue with NIO/Tomcat implementation. It may happens less frequently with 2.2.5-SNAPSHOT, but still the issue is with Tomcat.

Thanks

-- Jeanfrancois
On 2015-01-23 10:47 AM, Chris Boyd wrote:
Caused by: java.io.IOException: Key must be cancelled 
     at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:84) 
     at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:61) 
     at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:162)
Comment 1 Mark Thomas 2015-01-26 12:15:21 UTC
Hmm. Whatever is going wrong, is going wrong earlier than this stack trace.

Something causes the WebSocket connection to close. It appears that Atmosphere isn't notified about this / doesn't notice it.

Something happens later that causes Atmosphere to realise there is a dead WebSocket connection. Atmosphere triggers a 'dirty' close.

This 'dirty' close fails because the WebSocket connection has already been closed. That triggers an error because, as far as I can tell, a normal WebSocket close reason (1000) is used. If abnormal closure was used (1006), Tomcat would swallow any error.

What we really need to figure out is why is this connection closed in the first place. There isn't much in the way of debug logging for WebSocket session closure in Tomcat - I'll fix that for the next release - but it is worth seeing is Atmosphere's debug logging tells you anything useful.
Comment 2 Mark Thomas 2015-01-26 13:20:03 UTC
I've added some debig logging to trunk, 8.0.x (for 8.0.19 onwards) and 7.0.x (for 7.0.58 onwards). Any further information you can provide as to what is going on would be very helpful.
Comment 3 Jean-Francois Arcand 2015-01-27 20:29:31 UTC
@Mark,

I did hack a little to prevent that error (which I may not fixed completely)

https://github.com/Atmosphere/atmosphere/issues/1646

The stack trave will probably help you.
Comment 4 Mark Thomas 2015-02-03 10:55:38 UTC
I've just fixed some issues that might have triggered this sort of issue in trunk and 8.0.x. There is a development build of 8.0.19-dev here:
http://people.apache.org/~markt/dev/v8.0.19-dev/

Any feedback you can provide on testing with this or 8.0.x trunk would be great.
Comment 5 wodencafe 2015-02-04 21:11:22 UTC
Hi Mark,

I have been testing with the latest Trunk of 8.0.19, and verified that is the case with this line in the logs:

2015-02-04 15:06:02,796 CST INFO  [null] - Atmosphere is using async support: org.atmosphere.container.JSR356AsyncSupport running under container: Apache Tomcat/8.0.19-dev using javax.servlet/3.0 using javax.servlet/3.0 and jsr356/WebSocket API

Unfortunately, after interacting with the application for a brief amount of time, it hangs and we see the same exception:

2015-02-04 15:07:01,691 CST ERROR [null] - java.io.IOException: 
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:282)
	at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:570)
	at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:478)
	at org.apache.tomcat.websocket.WsSession.close(WsSession.java:445)
	at org.apache.tomcat.websocket.WsSession.close(WsSession.java:439)
	at org.atmosphere.container.version.JSR356WebSocket.close(JSR356WebSocket.java:104)
	at org.atmosphere.websocket.WebSocket.close(WebSocket.java:264)
	at org.atmosphere.cpr.AtmosphereResponse.close(AtmosphereResponse.java:836)
	at org.atmosphere.cpr.AtmosphereResourceImpl.cancel(AtmosphereResourceImpl.java:720)
	at org.atmosphere.cpr.AtmosphereResourceImpl.close(AtmosphereResourceImpl.java:785)
	at com.vaadin.server.communication.AtmospherePushConnection.disconnect(AtmospherePushConnection.java:294)
	at com.vaadin.server.communication.AtmospherePushConnection.connect(AtmospherePushConnection.java:232)
	at com.vaadin.server.communication.PushHandler$2.run(PushHandler.java:135)
	at com.vaadin.server.communication.PushHandler.callWithUi(PushHandler.java:253)
	at com.vaadin.server.communication.PushHandler.access$200(PushHandler.java:56)
	at com.vaadin.server.communication.PushHandler$1.onRequest(PushHandler.java:74)
	at org.atmosphere.cpr.AsynchronousProcessor.action(AsynchronousProcessor.java:174)
	at org.atmosphere.cpr.AsynchronousProcessor.suspended(AsynchronousProcessor.java:95)
	at org.atmosphere.container.Servlet30CometSupport.service(Servlet30CometSupport.java:66)
	at org.atmosphere.cpr.AtmosphereFramework.doCometSupport(AtmosphereFramework.java:1802)
	at org.atmosphere.websocket.DefaultWebSocketProcessor.dispatch(DefaultWebSocketProcessor.java:432)
	at org.atmosphere.websocket.DefaultWebSocketProcessor.open(DefaultWebSocketProcessor.java:186)
	at org.atmosphere.container.JSR356Endpoint.onOpen(JSR356Endpoint.java:160)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.init(WsHttpUpgradeHandler.java:138)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:687)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1558)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1515)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)
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:275)
	... 31 more
Caused by: java.io.IOException: Key must be cancelled
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:84)
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:61)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:162)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:129)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:99)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:450)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:338)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:270)
	... 31 more
Caused by: java.util.concurrent.ExecutionException:
	at org.apache.tomcat.websocket.FutureToSendHandler.get(FutureToSendHandler.java:102)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:275)
	at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:570)
	at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:478)
	at org.apache.tomcat.websocket.WsSession.close(WsSession.java:445)
	at org.apache.tomcat.websocket.WsSession.close(WsSession.java:439)
	at org.atmosphere.container.version.JSR356WebSocket.close(JSR356WebSocket.java:104)
	at org.atmosphere.websocket.WebSocket.close(WebSocket.java:264)
	at org.atmosphere.cpr.AtmosphereResponse.close(AtmosphereResponse.java:836)
	at org.atmosphere.cpr.AtmosphereResourceImpl.cancel(AtmosphereResourceImpl.java:720)
	at org.atmosphere.cpr.AtmosphereResourceImpl.close(AtmosphereResourceImpl.java:785)
	at com.vaadin.server.communication.AtmospherePushConnection.disconnect(AtmospherePushConnection.java:294)
	at com.vaadin.server.communication.AtmospherePushConnection.connect(AtmospherePushConnection.java:232)
	at com.vaadin.server.communication.PushHandler$2.run(PushHandler.java:135)
	at com.vaadin.server.communication.PushHandler.callWithUi(PushHandler.java:253)
	at com.vaadin.server.communication.PushHandler.access$200(PushHandler.java:56)
	at com.vaadin.server.communication.PushHandler$1.onRequest(PushHandler.java:74)
	at org.atmosphere.cpr.AsynchronousProcessor.action(AsynchronousProcessor.java:174)
	at org.atmosphere.cpr.AsynchronousProcessor.suspended(AsynchronousProcessor.java:95)
	at org.atmosphere.container.Servlet30CometSupport.service(Servlet30CometSupport.java:66)
	at org.atmosphere.cpr.AtmosphereFramework.doCometSupport(AtmosphereFramework.java:1802)
	at org.atmosphere.websocket.DefaultWebSocketProcessor.dispatch(DefaultWebSocketProcessor.java:432)
	at org.atmosphere.websocket.DefaultWebSocketProcessor.open(DefaultWebSocketProcessor.java:186)
	at org.atmosphere.container.JSR356Endpoint.onOpen(JSR356Endpoint.java:160)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.init(WsHttpUpgradeHandler.java:138)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:687)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1558)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1515)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: Key must be cancelled
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:84)
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:61)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:162)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:129)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:99)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:450)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:338)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:270)
	... 31 more
Comment 6 Mark Thomas 2015-02-04 21:40:08 UTC
Thanks for the feedback.

The CI system has highlighted a couple of issues with these fixes in place. I've just found what I think is another instance of multiple write registrations in trunk.

My plan is to get the CI system building trunk cleanly, port the fixes back to 8.0.x and then get the CI system for 8.0.x running cleanly. I don't think there is much benefit in you testing any more until the CI system says the build is clean. I'll ping this ticket when that is done.

Do you need me to build 8.0.x for you to test or are you happy building from svn?
Comment 7 wodencafe 2015-02-04 21:46:13 UTC
Hi Mark,

I am fine with building SVN, as long as I am doing it correctly :)

What I did today was I went into the directory where I had Tomcat trunk checked out, I ran "svn update", then "ant", and finally copied the built libs into my Tomcat 8 server for testing.

This is the correct process, right?

Let me know when to test again.

Thank you,

Chris Boyd
Comment 8 Christopher Schultz 2015-02-05 17:40:31 UTC
(In reply to wodencafe from comment #7)
> I ran "svn update", then "ant", and finally copied the built
> libs into my Tomcat 8 server for testing.

That's the correct procedure. If you are using split CATALINA_BASE and CATALINA_HOME (a great thing to do IMO), you can just point your CATALINA_HOME to the directory you have your svn working copy in, under output/build, something like this:

$ export CATALINA_BASE=[...]
$ export CATALINA_HOME=/path/to/tomcat-svn/output/build
$ $CATALINA_HOME/bin/catalina.sh start

You can always go back to your previous Tomcat (8.0.18, etc.) by switching CATALINA_HOME back to its previous value.
Comment 9 Mark Thomas 2015-02-10 15:55:49 UTC
OK. I've made various changes to 8.0.x that should at least make this less likely and hopefully prevent. If you could test with the current 8.0.x and let us know the results that would be great.
Comment 10 wodencafe 2015-02-10 22:07:52 UTC
Hi Mark,

I built Tomcat from Trunk and tested again.

Unfortunately the issue happened again, here is the Stack Trace:

2015-02-10 16:01:13,056 CST ERROR [null] - java.io.IOException: 
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:282)
	at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:570)
	at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:478)
	at org.apache.tomcat.websocket.WsSession.close(WsSession.java:445)
	at org.apache.tomcat.websocket.WsSession.close(WsSession.java:439)
	at org.atmosphere.container.version.JSR356WebSocket.close(JSR356WebSocket.java:104)
	at org.atmosphere.websocket.WebSocket.close(WebSocket.java:264)
	at org.atmosphere.cpr.AtmosphereResponse.close(AtmosphereResponse.java:836)
	at org.atmosphere.cpr.AtmosphereResourceImpl.cancel(AtmosphereResourceImpl.java:720)
	at org.atmosphere.cpr.AtmosphereResourceImpl.close(AtmosphereResourceImpl.java:785)
	at com.vaadin.server.communication.AtmospherePushConnection.disconnect(AtmospherePushConnection.java:294)
	at com.vaadin.server.communication.AtmospherePushConnection.connect(AtmospherePushConnection.java:232)
	at com.vaadin.server.communication.PushHandler$2.run(PushHandler.java:135)
	at com.vaadin.server.communication.PushHandler.callWithUi(PushHandler.java:253)
	at com.vaadin.server.communication.PushHandler.access$200(PushHandler.java:56)
	at com.vaadin.server.communication.PushHandler$1.onRequest(PushHandler.java:74)
	at org.atmosphere.cpr.AsynchronousProcessor.action(AsynchronousProcessor.java:174)
	at org.atmosphere.cpr.AsynchronousProcessor.suspended(AsynchronousProcessor.java:95)
	at org.atmosphere.container.Servlet30CometSupport.service(Servlet30CometSupport.java:66)
	at org.atmosphere.cpr.AtmosphereFramework.doCometSupport(AtmosphereFramework.java:1802)
	at org.atmosphere.websocket.DefaultWebSocketProcessor.dispatch(DefaultWebSocketProcessor.java:432)
	at org.atmosphere.websocket.DefaultWebSocketProcessor.open(DefaultWebSocketProcessor.java:186)
	at org.atmosphere.container.JSR356Endpoint.onOpen(JSR356Endpoint.java:160)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.init(WsHttpUpgradeHandler.java:138)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:687)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1558)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1515)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)
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:275)
	... 31 more
Caused by: java.io.IOException: Key must be cancelled
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:84)
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:61)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:165)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:132)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:99)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:450)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:338)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:270)
	... 31 more
Caused by: java.util.concurrent.ExecutionException:
	at org.apache.tomcat.websocket.FutureToSendHandler.get(FutureToSendHandler.java:102)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:275)
	at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:570)
	at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:478)
	at org.apache.tomcat.websocket.WsSession.close(WsSession.java:445)
	at org.apache.tomcat.websocket.WsSession.close(WsSession.java:439)
	at org.atmosphere.container.version.JSR356WebSocket.close(JSR356WebSocket.java:104)
	at org.atmosphere.websocket.WebSocket.close(WebSocket.java:264)
	at org.atmosphere.cpr.AtmosphereResponse.close(AtmosphereResponse.java:836)
	at org.atmosphere.cpr.AtmosphereResourceImpl.cancel(AtmosphereResourceImpl.java:720)
	at org.atmosphere.cpr.AtmosphereResourceImpl.close(AtmosphereResourceImpl.java:785)
	at com.vaadin.server.communication.AtmospherePushConnection.disconnect(AtmospherePushConnection.java:294)
	at com.vaadin.server.communication.AtmospherePushConnection.connect(AtmospherePushConnection.java:232)
	at com.vaadin.server.communication.PushHandler$2.run(PushHandler.java:135)
	at com.vaadin.server.communication.PushHandler.callWithUi(PushHandler.java:253)
	at com.vaadin.server.communication.PushHandler.access$200(PushHandler.java:56)
	at com.vaadin.server.communication.PushHandler$1.onRequest(PushHandler.java:74)
	at org.atmosphere.cpr.AsynchronousProcessor.action(AsynchronousProcessor.java:174)
	at org.atmosphere.cpr.AsynchronousProcessor.suspended(AsynchronousProcessor.java:95)
	at org.atmosphere.container.Servlet30CometSupport.service(Servlet30CometSupport.java:66)
	at org.atmosphere.cpr.AtmosphereFramework.doCometSupport(AtmosphereFramework.java:1802)
	at org.atmosphere.websocket.DefaultWebSocketProcessor.dispatch(DefaultWebSocketProcessor.java:432)
	at org.atmosphere.websocket.DefaultWebSocketProcessor.open(DefaultWebSocketProcessor.java:186)
	at org.atmosphere.container.JSR356Endpoint.onOpen(JSR356Endpoint.java:160)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.init(WsHttpUpgradeHandler.java:138)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:687)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1558)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1515)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: Key must be cancelled
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWriteInternal(NioServletOutputStream.java:84)
	at org.apache.coyote.http11.upgrade.NioServletOutputStream.doWrite(NioServletOutputStream.java:61)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.writeInternal(AbstractServletOutputStream.java:165)
	at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.write(AbstractServletOutputStream.java:132)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:99)
	at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:81)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:450)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:338)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:270)
	... 31 more

I see a couple of minor differences between this Stack Trace and the previous one, just in the line numbers of certain calls in a couple of places.

Please let me know when you need me to test more.
Comment 11 Mark Thomas 2015-02-11 18:18:00 UTC
I've fixed another issue. I don't think it will make any different but if you could do a quick test it would be appreciated.

I've just noticed that the stack trace passes through the onOpen method of the WebSocket Endpoint. That looks odd. I'm wondering if Atmosphere is doing something we didn't anticipate with the API. I'll look further but I don't expect to get this fixed for the next 8.0.x release. What I really need is a simple test case to reproduce this issue.
Comment 12 Mark Thomas 2015-02-16 12:55:43 UTC
A handful of additional fixes that might be related to this have gone into the 8.0.20 release candidate. An update on whether or not the issue is still present would be appreciated.
Comment 13 Mark Thomas 2015-04-22 10:38:22 UTC
No response for over two months. I'm going to assume that this is fixed. Please feel free to re-open if that is not the case. If the bug is still present, a test case to reproduce the issue will make it a lot easier to fix.
Comment 14 Barry Coughlan 2015-12-01 19:31:25 UTC
I can reproduce this on 8.0.29. I will create a proper test case that doesn't need breakpoints during the week.

Reproduced with the following:

    @OnMessage
    public void onMessage(Session session, ModelObject msg) {
        try {
            session.getBasicRemote().sendText("Test"); // <-- Breakpoint here
        } catch (IOException e) {
            e.printStackTrace();
        }
    }
1. Open websocket connection to the server
2. Send message from client to server, hits the breakpoint
3. Close the connection
4. Continue from the @OnMessage breakpoint

The following happens:

- Step 4 throws an exception as expected (java.io.IOException: An established connection was aborted by the software in your host machine) (we catch and log this exception)


- @OnError is called with a java.nio.channels.ClosedChannelException:
java.nio.channels.ClosedChannelException
	at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:256)
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:299)
	at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:137)
	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:66)
	at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:49)
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:183)
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:198)
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:96)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:669)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)


- Further attempts to send data on this session results in the "Key must be cancelled" exception:
java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:282)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPing(WsRemoteEndpointImplBase.java:174)
	at org.apache.tomcat.websocket.WsRemoteEndpointBase.sendPing(WsRemoteEndpointBase.java:55)
	at com.myapp.WsOutbound.sendPing(WsOutbound.java:295)
        .....

The @OnClose method is never called.
Comment 15 Mark Thomas 2015-12-01 20:58:27 UTC
I can't reproduce this using the current 8.0.x code. There is a fix that looks related: bug 58624
Comment 16 Barry Coughlan 2015-12-02 13:20:28 UTC
I just built the trunk and confirmed the same behaviour. Note that this only works with the NIO connector. I'll get back to you with a test case.
Comment 17 Barry Coughlan 2015-12-02 20:06:20 UTC
I tried creating a test for this today. It turns out that this problem only happens when a websocket is not closed with a proper closing handshake.

Most Websocket clients are quite polite when closing websockets, they will send a close frame and then wait for the handshake before closing the TCP connection. This means that the problem can't be replicated by doing session.close() in a Tomcat websocket client.

The reason that I can replicate this with Tyrus is that Tyrus sends a websocket close frame but then closes the TCP connection immediately without completing the handshake.

The steps with the example in my previous post and Tyrus CLI are:
1. Open connection
2. Send message, breaking in the @OnMessage
3. Close connection in Tyrus (or kill -9 the process to send just a TCP RST, the result is the same)
4. Resume @OnMessage (which sends a message)

Any suggestions on how to automate the test? Can I force a Tomcat client's socket to close without a handshake?
Comment 18 Barry Coughlan 2015-12-03 16:33:50 UTC
Created attachment 33321 [details]
Test cases for closing websockets
Comment 19 Barry Coughlan 2015-12-03 16:34:19 UTC
Created attachment 33322 [details]
Websocket client for testing TCP behaviour
Comment 20 Barry Coughlan 2015-12-03 16:35:54 UTC
Test cases attached - there are a few TODO comments in the attached files that could do with a pair of eyes. It's a bit messier than I had hoped but the test results match up with my manual testing.

Also, there is one scenario where the @OnMessage doesn't send a message but the @OnClose is not called - this happens only when a TCP reset is sent in the @OnMessage. This is captured in testTcpResetInOnMessage(). I'm not sure if the root cause is the same.
Comment 21 Mark Thomas 2015-12-04 14:02:22 UTC
Thanks for the test cases. I'm taking a look.
Comment 22 Barry Coughlan 2015-12-07 14:00:02 UTC
You've probably got this far already, but it seems that the cause for all of the test failures is this block in AbstractServletInputStream.java which swallows the exception:

        try {
            ready = Boolean.valueOf(doIsReady());
        } catch (IOException e) {
            onError(e);
        }

Throwing the exception in the catch block causes the tests to pass (although some awaitOnError() statements need to be modified).
Comment 23 Remy Maucherat 2015-12-07 14:13:23 UTC
This looks like what it should do however: call onError. Rethrowing in that method is not allowed.
Comment 24 Barry Coughlan 2015-12-07 14:54:18 UTC
(In reply to Remy Maucherat from comment #23)
> This looks like what it should do however: call onError. Rethrowing in that
> method is not allowed.

Sorry for not being clear - I wasn't suggesting that throwing the exception was a good fix (I'm not very familiar with the code), I was just using it to demonstrate that the issue lies there. Other read errors that occur in WsFrameServer.onDataAvailable() throw up the IOException so that onError/onClose is called, but swallowing the IOException in isReady() means that the onClose is never called.
Comment 25 Mark Thomas 2015-12-11 10:36:54 UTC
This has been fixed in 9.0.x although the connector refactoring means that a direct back-port may not be possible.

Note that two tests were removed because they were invalid as per section 2.1.5 of the WebSocket 1.1 specification.
Comment 26 Mark Thomas 2015-12-11 12:53:05 UTC
This issue identified in comment #22 did apply to 8.0.x and 7.0.x along with the issue identified in 9.0.x.

The back-ports have been completed and this fix will be included in 9.0.0.M2, 8.0.31 and 7.0.68 onwards.