Vertx-web: Force closing SockJSSocket causes deadlock

[gjroylance]

Hi,
I am trying to force close a SockJSSocket based off on an event generated by a different service. The following deadlock occurs when the client disappears at the same time I am closing the SockJSSocket (I am sure it's from a different event loop thread than what the socket is assigned to use). The use case I am trying to implement is a password reset, we want all connected clients with a particular id to be disconnected--clients could have multiple web sockets. Is there a way to safely force close a SockJSSocket without risking a deadlock? Could there be a way to use the writeHandlerID to send a close socket message?

This brings up another question, if the client signals a close at the same time the SockJSHandler closes the socket, is there a guarantee that a deadlock won't occur?

Found one Java-level deadlock:

"vert.x-eventloop-thread-1":
waiting to lock monitor 0x00007fafe8af5878 (object 0x000000076b5a3068, a io.vertx.ext.web.handler.sockjs.impl.SockJSSession),
which is held by "vert.x-worker-thread-1"
"vert.x-worker-thread-1":
waiting to lock monitor 0x00007fafe8af5928 (object 0x000000076b9337a8, a io.vertx.core.http.impl.ServerConnection),
which is held by "vert.x-eventloop-thread-1"

Java stack information for the threads listed above:

"vert.x-eventloop-thread-1":
at io.vertx.ext.web.handler.sockjs.impl.SockJSSession.shutdown(SockJSSession.java:179)

• waiting to lock <0x000000076b5a3068> (a io.vertx.ext.web.handler.sockjs.impl.SockJSSession)
  at io.vertx.ext.web.handler.sockjs.impl.BaseTransport$BaseListener$1.handle(BaseTransport.java:124)
  at io.vertx.core.VoidHandler.handle(VoidHandler.java:27)
  at io.vertx.core.VoidHandler.handle(VoidHandler.java:24)
  at io.vertx.core.http.impl.HttpServerResponseImpl.handleClosed(HttpServerResponseImpl.java:554)
• locked <0x000000076b9337a8> (a io.vertx.core.http.impl.ServerConnection)
  at io.vertx.core.http.impl.ServerConnection.handleClosed(ServerConnection.java:341)
• locked <0x000000076b9337a8> (a io.vertx.core.http.impl.ServerConnection)
  at io.vertx.core.net.impl.VertxHandler$$Lambda$173/33345994.run(Unknown Source)
  at io.vertx.core.impl.ContextImpl.lambda$wrapTask$18(ContextImpl.java:333)
  at io.vertx.core.impl.ContextImpl$$Lambda$9/1232475727.run(Unknown Source)
  at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
  at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:218)
  at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:204)
  at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:332)
  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:218)
  at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:204)
  at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
  at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:625)
  at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
  at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
  at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
  at java.lang.Thread.run(Thread.java:745)
  "vert.x-worker-thread-1":
  at io.vertx.core.http.impl.HttpServerResponseImpl.end(HttpServerResponseImpl.java:328)
• waiting to lock <0x000000076b9337a8> (a io.vertx.core.http.impl.ServerConnection)
  at io.vertx.ext.web.handler.sockjs.impl.XhrTransport$XhrPollingListener.close(XhrTransport.java:178)
  at io.vertx.ext.web.handler.sockjs.impl.XhrTransport$XhrPollingListener.sendFrame(XhrTransport.java:170)
  at io.vertx.ext.web.handler.sockjs.impl.SockJSSession.writeClosed(SockJSSession.java:376)
  at io.vertx.ext.web.handler.sockjs.impl.SockJSSession.writeClosed(SockJSSession.java:369)
  at io.vertx.ext.web.handler.sockjs.impl.BaseTransport$BaseListener.sessionClosed(BaseTransport.java:132)
  at io.vertx.ext.web.handler.sockjs.impl.SockJSSession.close(SockJSSession.java:191)
• locked <0x000000076b5a3068> (a io.vertx.ext.web.handler.sockjs.impl.SockJSSession)
  at io.vertx.rxjava.ext.web.handler.sockjs.SockJSSocket.close(SockJSSocket.java:145)

[rodolfocal]

We are facing the same problem in production: when we close SockJSSocket on the server side at the same time that the client is closing the connection, we get a deadlock between two vert.x-eventloop-threads.

In our case, the problem seems to be:
1 - thread 1 calls (after some timeout) SockJSSession.close() which is a synchronized method on SockJSSession.
2 - at the same time Netty detects the client has also closed the connection on their side.
3 - thread 2 calls HttpServerResponseImpl.handleClosed(), which has a synchronized statement on ServerConnection conn.
4 - later on, thread 2 calls SockJSSession.shutdown() (close handle callback for HttpServerResponse). SockJSSession.shutdown() is also a synchronized method on this sockJsSession object so it will not execute until thread 1 fully executes SockJSSession.close().
5 - later on, thread 1, still on SockJSSession.close() execution path, tries to call HttpServerResponseImpl.putHeader(HttpServerResponseImpl.java:153), which also has a synchronized statement on ServerConnection conn.

We still don’t have a solution for this.

Following is the stack trace:

Thread 1:
Mar 23 17:58:27 srv jsvc.exec[21412]: Mar 23, 2016 5:58:27 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-6,5,main] has been blocked for 285283141 ms, time limit is 2000
io.vertx.core.VertxException: Thread blocked
at io.vertx.core.http.impl.HttpServerResponseImpl.putHeader(HttpServerResponseImpl.java:153)
at io.vertx.core.http.impl.HttpServerResponseImpl.putHeader(HttpServerResponseImpl.java:52)
at io.vertx.ext.web.handler.sockjs.impl.XhrTransport$BaseXhrListener.sendFrame(XhrTransport.java:148)
at io.vertx.ext.web.handler.sockjs.impl.XhrTransport$XhrPollingListener.sendFrame(XhrTransport.java:168)
at io.vertx.ext.web.handler.sockjs.impl.SockJSSession.writeClosed(SockJSSession.java:376)
at io.vertx.ext.web.handler.sockjs.impl.SockJSSession.writeClosed(SockJSSession.java:369)
at io.vertx.ext.web.handler.sockjs.impl.BaseTransport$BaseListener.sessionClosed(BaseTransport.java:132)
at io.vertx.ext.web.handler.sockjs.impl.SockJSSession.close(SockJSSession.java:191)
at wss.WSSSocketHandler$ConsumerC
Mar 23 17:58:27 srv jsvc.exec[21412]: ontext.destroyContext(WSSSocketHandler.java:282)
at wss.WSSSocketHandler$ConsumerContext.lambda$0(WSSSocketHandler.java:268)
at wss.WSSSocketHandler$ConsumerContext$$Lambda$137/633765.handle(Unknown Source)
at io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:738)
at io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:709)
at io.vertx.core.impl.ContextImpl.lambda$wrapTask$18(ContextImpl.java:335)
at io.vertx.core.impl.ContextImpl$$Lambda$13/806055926.run(Unknown Source)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)

Thread 2:
Mar 23 17:58:27 srv jsvc.exec[21412]: Mar 23, 2016 5:58:27 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-10,5,main] has been blocked for 285283141 ms, time limit is 2000
io.vertx.core.VertxException: Thread blocked
at io.vertx.ext.web.handler.sockjs.impl.SockJSSession.shutdown(SockJSSession.java:179)
at io.vertx.ext.web.handler.sockjs.impl.BaseTransport$BaseListener$1.handle(BaseTransport.java:124)
at io.vertx.core.VoidHandler.handle(VoidHandler.java:27)
at io.vertx.core.VoidHandler.handle(VoidHandler.java:24)
at io.vertx.core.http.impl.HttpServerResponseImpl.handleClosed(HttpServerResponseImpl.java:554)
at io.vertx.core.http.impl.ServerConnection.handleClosed(ServerConnection.java:341)
at io.vertx.core.net.impl.VertxHandler$$Lambda$152/1517397497.run(Unknown Source)
at io.vertx.core.impl.ContextImpl.lambda$wrapTask$18(ContextImpl.java:333)
at io.vertx.core.impl.ContextImpl$$Lambda$13/806055926.run(Unknown Source)
at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
at io.ve
Mar 23 17:58:27 srv jsvc.exec[21412]: rtx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:218)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:204)
at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:332)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:218)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:204)
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:625)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(S
Mar 23 17:58:27 sv jsvc.exec[21412]: ingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)

[vietj]

it seems similar to this case already opened : https://github.com/vert-x3/vertx-web/issues/310

[vietj]

you should close the sock js session from the correct event loop, the writeHandlerID is only for sending message to the websocket.

Since you are closing the SockJSSocket yourself it means you have a reference on the object. So it seems that you could register along with the SockJSSocket, the Context of this socket and then do:

context.runOnContext(() -> socket.close());

You can get the context of the socket when it is created with vertx.getOrCreateContext()

this would ensure no deadlock.

[rodolfocal]

Hi, thanks for the quick response.
I'm afraid we already run socket.close() on the right context. Im my opinion, the connection close event captured from Netty is the one which runs in the wrong context, but I have no control of it.

This closeHandler in BaseTransport.java is the one (I guess) not running on same event loop:

protected void addCloseHandler(HttpServerResponse resp, final SockJSSession session) {
  resp.closeHandler(new VoidHandler() {
    public void handle() {
      if (log.isTraceEnabled()) log.trace("Connection closed (from client?), closing session");
      // Connection has been closed from the client or network error so
      // we remove the session
      session.shutdown();
      closed = true;
    }
  });
}

[vietj]

could you provide a reproducer ?

[rodolfocal]

Hi, I have put a reproducer at https://github.com/rodolfocal/sockjs-deadlock.

[vietj]

great, thanks that will allow someone to investigate this problem

[purplefox]

I've had a quick look (haven't run it yet).

A couple of questions:

1. Why is context.runOnContext being used to close the socket?

context.runOnContext( v -> {
System.out.println("from context : " + Thread.currentThread().getName());
sockJSSocket.close();
});

1. Can you verify that the three System.out.println statements always display the same thread for the same verticle instance? (from handler, from timeout, from context).

(Maybe you could provide the output, and add something to distinguish verticle instance)

[rodolfocal]

1 - Just to rule out this option. But, yes, it is useless: handler and callback code already run on the same thread. We don't have this "context.runOnContext" in production either.

2 - Yes, the three run on the same thread and same verticle instance. I have added a "this.toString()" in the System.out.println statement. I have also updated the README with an output.

[vietj]

see https://github.com/vert-x3/vertx-web/tree/sockjs-session-tests

[vietj]

see also https://github.com/vert-x3/vertx-web/issues/501

[vietj]

the point that was missed in this case (and other) is that the SockJS session can be accessed by different event loops because the transport reconnects with a different connection from the browser likely with a different event loop.

User code (or event the event bus bridge) will have been using the initial event loop when the SockJSSsocket was handed off to the handler and later operate on this event loop.

The close event after reconnect will be executed on the event loop assigned when the client reconnected.

One simple solution is that the close event user callbacks from HttpServerRequest/ServerWebSocket are not executed holding the lock (i.e with an extra runOnContext).

[vietj]

@rodolfocal I know it's been a long time but could you run your reproducer with this Vert.x Core branch ? https://github.com/eclipse/vert.x/tree/dont-call-http-server-close-handler-holding-locks

[rodolfocal]

Hi @vietj, sure. As soon as I have the time I will test it and let you know.

[vietj]

should be fixed - added test https://github.com/vert-x3/vertx-web/commit/588f408675da610c73e88b03b8ae6835033105a3

[rodolfocal]

Hi @vietj I tried https://github.com/eclipse/vert.x/tree/dont-call-http-server-close-handler-holding-locks and was not able to reproduce the issue 👍