https://issues.apache.org/bugzilla/show_bug.cgi?id=54711
Bug ID: 54711
Summary: Strange problem with WsOutputStream; cannot write to
it, Session gets closed instead
Product: Tomcat 8
Version: trunk
Hardware: All
OS: All
Status: NEW
Severity: blocker
Priority: P2
Component: Catalina
Assignee: dev@tomcat.apache.org
Reporter: nicho...@nicholaswilliams.net
Classification: Unclassified
Created attachment 30059
--> https://issues.apache.org/bugzilla/attachment.cgi?id=30059&action=edit
Thread dump when blocking
I'm attempting to write a binary message using the OutputStream returned by
RemoteEndpoint.Basic#getSendStream(). The code that is doing this is as
follows:
@Override
protected void doGet(HttpServletRequest request, HttpServletResponse
response)
throws ServletException, IOException
{
ClusterMessage message = new ClusterMessage();
message.setNodeId(this.nodeId);
message.setMessage("request:{ip:\"" + request.getRemoteAddr() +
"\",queryString:\"" + request.getQueryString() + "\"}");
try(OutputStream output =
this.session.getBasicRemote().getSendStream();
ObjectOutputStream stream = new ObjectOutputStream(output))
{
stream.writeObject(message);
}
response.getWriter().append("OK");
}
When I perform this request, the browser waits for a response forever. It never
stops. Assuming there was an infinite loop somewhere, I took a thread dump
(attached). An exception was logged to stderr pretty much instantaneously when
I make the request:
Exception in thread "Thread-18" java.lang.IllegalStateException: Message will
not be sent because the WebSocket session has been closed
at
org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:270)
at
org.apache.tomcat.websocket.WsRemoteEndpointImplBase.endMessage(WsRemoteEndpointImplBase.java:256)
at
org.apache.tomcat.websocket.WsRemoteEndpointImplBase$EndMessageHandler.onResult(WsRemoteEndpointImplBase.java:398)
at
org.apache.tomcat.websocket.WsRemoteEndpointImplBase$OutputBufferSendHandler.write(WsRemoteEndpointImplBase.java:647)
at
org.apache.tomcat.websocket.WsRemoteEndpointImplBase$OutputBufferSendHandler.onResult(WsRemoteEndpointImplBase.java:656)
at
org.apache.tomcat.websocket.WsRemoteEndpointImplClient$SendHandlerToCompletionHandler.completed(WsRemoteEndpointImplClient.java:77)
at
org.apache.tomcat.websocket.WsRemoteEndpointImplClient$SendHandlerToCompletionHandler.completed(WsRemoteEndpointImplClient.java:66)
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:269)
at
sun.nio.ch.WindowsAsynchronousSocketChannelImpl$WriteTask.completed(WindowsAsynchronousSocketChannelImpl.java:814)
at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:397)
at
sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
And I get some disconcerting log entries when I shut Tomcat down:
Mar 17, 2013 5:22:42 AM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 1 instance(s) to be deallocated
Mar 17, 2013 5:22:43 AM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 1 instance(s) to be deallocated
Mar 17, 2013 5:22:44 AM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 1 instance(s) to be deallocated
Mar 17, 2013 5:22:44 AM org.apache.catalina.loader.WebappClassLoader
clearReferencesThreads
SEVERE: The web application [/myWebApp] appears to have started a thread named
[WebSocket background processing] but has failed to stop it. This is very
likely to create a memory leak.
Mar 17, 2013 5:22:44 AM org.apache.catalina.loader.WebappClassLoader
clearReferencesThreads
SEVERE: The web application [/myWebApp] is still processing a request that has
yet to finish. This is very likely to create a memory leak. You can control the
time allowed for requests to finish by using the unloadDelay attribute of the
standard Context implementation.
Mar 17, 2013 5:22:44 AM org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["http-nio-8080"]
Mar 17, 2013 5:22:44 AM org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["ajp-nio-8009"]
Mar 17, 2013 5:22:44 AM
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.NullPointerException
at
org.apache.coyote.http11.Http11NioProcessor.isRegisteredForWrite(Http11NioProcessor.java:250)
at
org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:237)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:620)
at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1581)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1540)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
Mar 17, 2013 5:22:44 AM org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["http-nio-8080"]
Mar 17, 2013 5:22:44 AM org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["ajp-nio-8009"]
At this point I tried to look for the infinite loop. The first problem I found
was o.a.t.websocket.WsRemoteEndpointImplBase.WsOutputStream, even though the
thread dump does not suggest that this is where the problem is:
@Override
public void write(byte[] b, int off, int len) throws IOException {
int remaining = buffer.remaining();
int written = 0;
while (remaining < len) {
buffer.put(b, off + written, remaining);
written += remaining;
flush();
remaining = buffer.remaining();
}
buffer.put(b, off + written, len - written);
}
If len is ever greater than the remaining buffer size, this method will never
complete. I improved the method like so:
@Override
public void write(byte[] b, int off, int len) throws IOException {
if (buffer.remaining() == 0) {
flush();
}
int remaining = buffer.remaining();
int written = 0;
while (remaining < len/* - written*/) {
buffer.put(b, off + written, remaining);
written += remaining;
flush();
remaining = buffer.remaining();
}
buffer.put(b, off + written, len - written);
}
This (obviously) did not resolve the infinite loop problem (though I AM
confident that it fixes a bug that just hasn't been seen yet). Thread dumps all
look the same over and over again. The symptom is intermittent: the thread dump
shows that every call to WsOutputStream#close() is hanging, but sometimes the
respons returns to the browser anyway (even though the message never sends).
At this point, after working on it for five hours, it is beyond my
Tomcat/WebSocket expertise to solve. Which is unfortunate. I really needed this
today. :-(
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
