I am using Openfire 3.10.2. I have experienced a deadlock, see below:
I think the issue is in NIOConnection.java: close() is being called twice (recursion) and so the lock it obtains is not actually released when
notifyCloseListeners is called by the “C2S-Thread-4” thread within the 2nd invocation of close(). I have a fix in mind but realize there have been some churn in this area
over the last 6 months so would like input from the experts.
I am thinking that close() should return if state == state.CLOSED or stat==state.CLOSING.
Thanks
Peter
Found one Java-level deadlock:
2015-11-12 11:59:36,826 : openfire-output : =============================
2015-11-12 11:59:36,826 : openfire-output : “Jetty-QTP-AdminConsole-17897”:
2015-11-12 11:59:36,827 : openfire-output : waiting to lock monitor 0x00007fa7600c8ba8 (object 0x00000000e0da14d8, a java.lang.String),
2015-11-12 11:59:36,827 : openfire-output : which is held by “C2S-Thread-3”
2015-11-12 11:59:36,827 : openfire-output : “C2S-Thread-3”:
2015-11-12 11:59:36,827 : openfire-output : waiting to lock monitor 0x00007fa76800aba8 (object 0x00000000e0d259b8, a org.jivesoftware.openfire.nio.NIOConnection),
2015-11-12 11:59:36,827 : openfire-output : which is held by “C2S-Thread-4”
2015-11-12 11:59:36,827 : openfire-output : “C2S-Thread-4”:
2015-11-12 11:59:36,827 : openfire-output : waiting to lock monitor 0x00007fa7600c8ba8 (object 0x00000000e0da14d8, a java.lang.String),
2015-11-12 11:59:36,827 : openfire-output : which is held by “C2S-Thread-3”
2015-11-12 11:59:36,827 : openfire-output :
2015-11-12 11:59:36,827 : openfire-output : Java stack information for the threads listed above:
2015-11-12 11:59:36,827 : openfire-output : ===================================================
2015-11-12 11:59:36,827 : openfire-output : “Jetty-QTP-AdminConsole-17897”:
2015-11-12 11:59:36,827 : openfire-output : at org.jivesoftware.openfire.roster.RosterManager.getRoster(RosterManager.java:113 )
2015-11-12 11:59:36,827 : openfire-output : - waiting to lock <0x00000000e0da14d8> (a java.lang.String)
2015-11-12 11:59:36,827 : openfire-output : at org.jivesoftware.openfire.handler.PresenceUpdateHandler.broadcastUpdate(Presenc eUpdateHandler.java:307)
2015-11-12 11:59:36,827 : openfire-output : at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:162)
2015-11-12 11:59:36,827 : openfire-output : at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:137)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:201)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:148)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.PresenceRouter.route(PresenceRouter.java:84)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:84)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.SessionManager$ClientSessionListener.onConnectionClos e(SessionManager.java:1242)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.notifyCloseListeners(NIOConnection. java:292)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:275)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:224)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.deliverRawText(NIOConnection.java:3 96)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:246)
2015-11-12 11:59:36,828 : openfire-output : - locked <0x00000000e10c4d80> (a org.jivesoftware.openfire.nio.NIOConnection)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:224)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.deliverRawText(NIOConnection.java:3 96)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.validate(NIOConnection.java:142)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.session.LocalSession.validate(LocalSession.java:350)
2015-11-12 11:59:36,828 : openfire-output : at org.jivesoftware.openfire.admin.session_002dsummary_jsp._jspService(session_002 dsummary_jsp.java:318)
2015-11-12 11:59:36,828 : openfire-output : at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
2015-11-12 11:59:36,828 : openfire-output : at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.ja va:1669)
2015-11-12 11:59:36,829 : openfire-output : at com.opensymphony.module.sitemesh.filter.PageFilter.parsePage(PageFilter.java:11 8)
2015-11-12 11:59:36,829 : openfire-output : at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:52)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.ja va:1652)
2015-11-12 11:59:36,829 : openfire-output : at org.jivesoftware.util.LocaleFilter.doFilter(LocaleFilter.java:74)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.ja va:1652)
2015-11-12 11:59:36,829 : openfire-output : at org.jivesoftware.util.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingF ilter.java:50)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.ja va:1652)
2015-11-12 11:59:36,829 : openfire-output : at org.jivesoftware.admin.PluginFilter.doFilter(PluginFilter.java:78)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.ja va:1652)
2015-11-12 11:59:36,829 : openfire-output : at org.jivesoftware.admin.AuthCheckFilter.doFilter(AuthCheckFilter.java:159)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.ja va:1652)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
2015-11-12 11:59:36,829 : openfire-output : at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:22 3)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:11 27)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185 )
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:106 1)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandler Collection.java:215)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.jav a:110)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.Server.handle(Server.java:497)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635 )
2015-11-12 11:59:36,830 : openfire-output : at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
2015-11-12 11:59:36,830 : openfire-output : at java.lang.Thread.run(Thread.java:745)
2015-11-12 11:59:36,830 : openfire-output : “C2S-Thread-3”:
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:233)
2015-11-12 11:59:36,831 : openfire-output : - waiting to lock <0x00000000e0d259b8> (a org.jivesoftware.openfire.nio.NIOConnection)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:224)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.deliver(NIOConnection.java:353)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.session.LocalClientSession.deliver(LocalClientSession .java:857)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.session.LocalSession.process(LocalSession.java:289)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.spi.RoutingTableImpl.routeToLocalDomain(RoutingTableI mpl.java:354)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.spi.RoutingTableImpl.routePacket(RoutingTableImpl.jav a:239)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.SessionManager.userBroadcast(SessionManager.java:1068 )
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.roster.Roster.broadcast(Roster.java:685)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.roster.Roster.broadcast(Roster.java:718)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.roster.Roster.(Roster.java:163)
2015-11-12 11:59:36,831 : openfire-output : at org.jivesoftware.openfire.roster.RosterManager.getRoster(RosterManager.java:116 )
2015-11-12 11:59:36,831 : openfire-output : - locked <0x00000000e0da14d8> (a java.lang.String)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.user.User.getRoster(User.java:389)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.handler.IQRosterHandler.manageRoster(IQRosterHandler. java:187)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.handler.IQRosterHandler.handleIQ(IQRosterHandler.java :122)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.handler.IQHandler.process(IQHandler.java:65)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:380)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:123)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:76)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:330)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler .java:93)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:295)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:187)
2015-11-12 11:59:36,832 : openfire-output : at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandl er.java:177)
2015-11-12 11:59:36,832 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceive d(DefaultIoFilterChain.java:690)
2015-11-12 11:59:36,832 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(D efaultIoFilterChain.java:417)
2015-11-12 11:59:36,832 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilt erChain.java:47)
2015-11-12 11:59:36,832 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceiv ed(DefaultIoFilterChain.java:765)
2015-11-12 11:59:36,832 : openfire-output : at org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapte r.java:109)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(D efaultIoFilterChain.java:417)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilt erChain.java:47)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceiv ed(DefaultIoFilterChain.java:765)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.filter.codec.ProtocolCodecFilter$ProtocolDecoderOutputImpl.flus h(ProtocolCodecFilter.java:407)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:236)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(D efaultIoFilterChain.java:417)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilt erChain.java:47)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceiv ed(DefaultIoFilterChain.java:765)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(Ordere dThreadPoolExecutor.java:769)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(Order edThreadPoolExecutor.java:761)
2015-11-12 11:59:36,833 : openfire-output : at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(OrderedThr eadPoolExecutor.java:703)
2015-11-12 11:59:36,833 : openfire-output : at java.lang.Thread.run(Thread.java:745)
2015-11-12 11:59:36,833 : openfire-output : “C2S-Thread-4”:
2015-11-12 11:59:36,833 : openfire-output : at org.jivesoftware.openfire.roster.RosterManager.getRoster(RosterManager.java:113 )
2015-11-12 11:59:36,833 : openfire-output : - waiting to lock <0x00000000e0da14d8> (a java.lang.String)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.handler.PresenceUpdateHandler.broadcastUpdate(Presenc eUpdateHandler.java:307)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:162)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:137)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:201)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:148)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.PresenceRouter.route(PresenceRouter.java:84)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:84)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.SessionManager$ClientSessionListener.onConnectionClos e(SessionManager.java:1242)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.notifyCloseListeners(NIOConnection. java:292)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:275)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:224)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.deliverRawText(NIOConnection.java:3 96)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:246)
2015-11-12 11:59:36,834 : openfire-output : - locked <0x00000000e0d259b8> (a org.jivesoftware.openfire.nio.NIOConnection)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:224)
2015-11-12 11:59:36,834 : openfire-output : at org.jivesoftware.openfire.nio.ConnectionHandler.sessionClosed(ConnectionHandler .java:107)
2015-11-12 11:59:36,834 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.sessionClosed( DefaultIoFilterChain.java:642)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(Def aultIoFilterChain.java:382)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilte rChain.java:47)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed (DefaultIoFilterChain.java:750)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.IoFilterAdapter.sessionClosed(IoFilterAdapter. java:88)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(Def aultIoFilterChain.java:382)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilte rChain.java:47)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed (DefaultIoFilterChain.java:750)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.filter.codec.ProtocolCodecFilter.sessionClosed(ProtocolCodecFil ter.java:369)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(Def aultIoFilterChain.java:382)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilte rChain.java:47)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed (DefaultIoFilterChain.java:750)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:109)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(Ordere dThreadPoolExecutor.java:769)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(Order edThreadPoolExecutor.java:761)
2015-11-12 11:59:36,835 : openfire-output : at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(OrderedThr eadPoolExecutor.java:703)
2015-11-12 11:59:36,835 : openfire-output : at java.lang.Thread.run(Thread.java:745)
2015-11-12 11:59:36,836 : openfire-output :
2015-11-12 11:59:36,836 : openfire-output : Found 1 deadlock.