ICEfaces
  1. ICEfaces
  2. ICE-9627

Deadlock during session invalidation

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: EE-1.8.2.GA_P07
    • Fix Version/s: EE-1.8.2.GA_P08
    • Component/s: Framework
    • Labels:
      None
    • Environment:
      WebLogic Seam
    • Salesforce Case Reference:

      Description

      It appears we have interleaved synchronization that is causing a deadlock. It is triggered during session invalidation. In this case, something in Seam is invalidating the session and that invalidate call makes it's way down until we try to shutdown our SessionDispatcher.Monitor. At that point it grabs a lock on the collection of "contexts" in order to iterate through and clean up stuff. During this process, though, it needs to grap a lock on the SessionMonitors collection. Unfortunately, a thread already has the lock but then needs the lock on the "contexts" collection as well.
      1. ICE-9627.patch
        2 kB
        Deryk Sinotte
      2. icefaces.death.threadDump
        139 kB
        Arran Mccullough
      3. synchronizeInShutdown.patch
        2 kB
        Arran Mccullough

        Activity

        Hide
        Deryk Sinotte added a comment -

        This is the invalidation thread involved in the deadlock:

        "[ACTIVE] ExecuteThread: '49' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaadc235000 nid=0x77e7 waiting for monitor entry [0x000000004b133000]
           java.lang.Thread.State: BLOCKED (on object monitor)
        	at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.notifySessionShutdown(SessionDispatcher.java:272)
        	- waiting to lock <0x00000004e1dd64c0> (a java.util.HashMap)
        	at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.access$400(SessionDispatcher.java:73)
        	at com.icesoft.faces.webapp.http.servlet.SessionDispatcher$Monitor.shutdown(SessionDispatcher.java:441)
        	- locked <0x000000057b3f14d8> (a java.util.Collections$SynchronizedSet)
        	at com.icesoft.faces.webapp.http.servlet.InterceptingServletSession.invalidate(InterceptingServletSession.java:54)
        	at sun.reflect.GeneratedMethodAccessor2248.invoke(Unknown Source)
        	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        	at java.lang.reflect.Method.invoke(Method.java:597)
        	at org.jboss.seam.contexts.FacesLifecycle.invalidateSession(FacesLifecycle.java:158)
        	at org.jboss.seam.contexts.FacesLifecycle.endRequest(FacesLifecycle.java:135)
        	at org.jboss.seam.jsf.SeamPhaseListener.afterResponseComplete(SeamPhaseListener.java:524)
        	at org.jboss.seam.jsf.SeamPhaseListener.afterServletPhase(SeamPhaseListener.java:252)
        	at org.jboss.seam.jsf.SeamPhaseListener.afterPhase(SeamPhaseListener.java:195)
        	at com.sun.faces.lifecycle.Phase.handleAfterPhase(Phase.java:175)
        	at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:114)
        	at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118)
        	at com.icesoft.faces.webapp.http.core.JsfLifecycleExecutor.apply(JsfLifecycleExecutor.java:50)
        	at com.icesoft.faces.webapp.http.core.ReceiveSendUpdates.renderCycle(ReceiveSendUpdates.java:169)
        	at com.icesoft.faces.webapp.http.core.ReceiveSendUpdates.service(ReceiveSendUpdates.java:110)
        	at com.icesoft.faces.webapp.http.core.RequestVerifier.service(RequestVerifier.java:65)
        	at com.icesoft.faces.webapp.http.servlet.BasicAdaptingServlet.service(BasicAdaptingServlet.java:51)
        	at com.icesoft.faces.webapp.http.servlet.SessionVerifier.service(SessionVerifier.java:62)
        	at com.icesoft.faces.webapp.http.servlet.PathDispatcher.service(PathDispatcher.java:55)
        	at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.service(SessionDispatcher.java:106)
        	at com.icesoft.faces.webapp.http.servlet.BlockExpiredSessionRequests.service(BlockExpiredSessionRequests.java:53)
        	at com.icesoft.faces.webapp.http.servlet.PathDispatcher.service(PathDispatcher.java:55)
        	at com.icesoft.faces.webapp.http.servlet.MainServlet.service(MainServlet.java:204)
        	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        	at com.icesoft.faces.webapp.xmlhttp.BlockingServlet.service(BlockingServlet.java:71)
        ...

        And this is the other:

        "[ACTIVE] ExecuteThread: '35' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaad8cf0800 nid=0x5804 waiting for monitor entry [0x000000004a528000]
           java.lang.Thread.State: BLOCKED (on object monitor)
        	at java.util.Collections$SynchronizedCollection.add(Collections.java:1577)
        	- waiting to lock <0x000000057b3f14d8> (a java.util.Collections$SynchronizedSet)
        	at com.icesoft.faces.webapp.http.servlet.SessionDispatcher$Monitor.addInSessionContext(SessionDispatcher.java:459)
        	at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.checkSession(SessionDispatcher.java:142)
        	- locked <0x00000004e1dd64c0> (a java.util.HashMap)
        	at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.service(SessionDispatcher.java:96)
        	at com.icesoft.faces.webapp.http.servlet.BlockExpiredSessionRequests.service(BlockExpiredSessionRequests.java:53)
        	at com.icesoft.faces.webapp.http.servlet.PathDispatcher.service(PathDispatcher.java:55)
        	at com.icesoft.faces.webapp.http.servlet.MainServlet.service(MainServlet.java:204)
        	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        	at com.icesoft.faces.webapp.xmlhttp.BlockingServlet.service(BlockingServlet.java:71)

        In thread '49', the session has been invalidated and the SessionDispatcher is attempting to shut down the Monitor for that session. In the process of doing that it grabs the lock on the contexts instance (a synchronized Set):

        ...
        private Set contexts = Collections.synchronizedSet(new HashSet());
        ...
        public void shutdown() {
            //notify all the contexts associated to this monitored session
            synchronized (contexts){
                Iterator i = contexts.iterator();
                while (i.hasNext()) {
                    ServletContext context = (ServletContext) i.next();
                    notifySessionShutdown(session, context);
        ...

        As part of notifySessionShutdown(), it wants to grab the lock for the SessionMonitors (a plain HashMap):

        ...
        private static void notifySessionShutdown(final HttpSession session, final ServletContext context) {
            SessionDispatcher sessionDispatcher = lookupSessionDispatcher(context);
            if (sessionDispatcher != null) {
                sessionDispatcher.notifySessionShutdown(session);
        
                synchronized (SessionMonitors) {
        ...
        

        In thread '35', we see that it grabbed the lock for the SessionMonitors:

        protected void checkSession(HttpSession session) throws SessionExpiredException {
            try {
                final String id = getId(session);
                final Monitor monitor;
                synchronized (SessionMonitors) {
                    if (!SessionMonitors.containsKey(id)) {
                        monitor = new Monitor(id, session);
                        SessionMonitors.put(id, monitor);
                    } else {
                        monitor = (Monitor) SessionMonitors.get(id);
                    }
                    //it is possible to have multiple web-app contexts associated with the same session ID
                    monitor.addInSessionContext(context);

        But as part of calling addInSessionContext(), it needs the lock on the contexts (a synchronized Set) instance being held by thread '49':

        public void addInSessionContext(ServletContext context) {
            contexts.add(context);
        }

        Subsequent request threads just start piling up waiting on the lock for the SessionMonitors:

        "[ACTIVE] ExecuteThread: '51' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaadc214000 nid=0x77e9 waiting for monitor entry [0x000000004b336000]
           java.lang.Thread.State: BLOCKED (on object monitor)
        	at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.checkSession(SessionDispatcher.java:135)
        	- waiting to lock <0x00000004e1dd64c0> (a java.util.HashMap)
        Show
        Deryk Sinotte added a comment - This is the invalidation thread involved in the deadlock: "[ACTIVE] ExecuteThread: '49' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaadc235000 nid=0x77e7 waiting for monitor entry [0x000000004b133000] java.lang.Thread.State: BLOCKED (on object monitor) at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.notifySessionShutdown(SessionDispatcher.java:272) - waiting to lock <0x00000004e1dd64c0> (a java.util.HashMap) at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.access$400(SessionDispatcher.java:73) at com.icesoft.faces.webapp.http.servlet.SessionDispatcher$Monitor.shutdown(SessionDispatcher.java:441) - locked <0x000000057b3f14d8> (a java.util.Collections$SynchronizedSet) at com.icesoft.faces.webapp.http.servlet.InterceptingServletSession.invalidate(InterceptingServletSession.java:54) at sun.reflect.GeneratedMethodAccessor2248.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.jboss.seam.contexts.FacesLifecycle.invalidateSession(FacesLifecycle.java:158) at org.jboss.seam.contexts.FacesLifecycle.endRequest(FacesLifecycle.java:135) at org.jboss.seam.jsf.SeamPhaseListener.afterResponseComplete(SeamPhaseListener.java:524) at org.jboss.seam.jsf.SeamPhaseListener.afterServletPhase(SeamPhaseListener.java:252) at org.jboss.seam.jsf.SeamPhaseListener.afterPhase(SeamPhaseListener.java:195) at com.sun.faces.lifecycle.Phase.handleAfterPhase(Phase.java:175) at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:114) at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118) at com.icesoft.faces.webapp.http.core.JsfLifecycleExecutor.apply(JsfLifecycleExecutor.java:50) at com.icesoft.faces.webapp.http.core.ReceiveSendUpdates.renderCycle(ReceiveSendUpdates.java:169) at com.icesoft.faces.webapp.http.core.ReceiveSendUpdates.service(ReceiveSendUpdates.java:110) at com.icesoft.faces.webapp.http.core.RequestVerifier.service(RequestVerifier.java:65) at com.icesoft.faces.webapp.http.servlet.BasicAdaptingServlet.service(BasicAdaptingServlet.java:51) at com.icesoft.faces.webapp.http.servlet.SessionVerifier.service(SessionVerifier.java:62) at com.icesoft.faces.webapp.http.servlet.PathDispatcher.service(PathDispatcher.java:55) at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.service(SessionDispatcher.java:106) at com.icesoft.faces.webapp.http.servlet.BlockExpiredSessionRequests.service(BlockExpiredSessionRequests.java:53) at com.icesoft.faces.webapp.http.servlet.PathDispatcher.service(PathDispatcher.java:55) at com.icesoft.faces.webapp.http.servlet.MainServlet.service(MainServlet.java:204) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at com.icesoft.faces.webapp.xmlhttp.BlockingServlet.service(BlockingServlet.java:71) ... And this is the other: "[ACTIVE] ExecuteThread: '35' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaad8cf0800 nid=0x5804 waiting for monitor entry [0x000000004a528000] java.lang.Thread.State: BLOCKED (on object monitor) at java.util.Collections$SynchronizedCollection.add(Collections.java:1577) - waiting to lock <0x000000057b3f14d8> (a java.util.Collections$SynchronizedSet) at com.icesoft.faces.webapp.http.servlet.SessionDispatcher$Monitor.addInSessionContext(SessionDispatcher.java:459) at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.checkSession(SessionDispatcher.java:142) - locked <0x00000004e1dd64c0> (a java.util.HashMap) at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.service(SessionDispatcher.java:96) at com.icesoft.faces.webapp.http.servlet.BlockExpiredSessionRequests.service(BlockExpiredSessionRequests.java:53) at com.icesoft.faces.webapp.http.servlet.PathDispatcher.service(PathDispatcher.java:55) at com.icesoft.faces.webapp.http.servlet.MainServlet.service(MainServlet.java:204) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at com.icesoft.faces.webapp.xmlhttp.BlockingServlet.service(BlockingServlet.java:71) In thread '49', the session has been invalidated and the SessionDispatcher is attempting to shut down the Monitor for that session. In the process of doing that it grabs the lock on the contexts instance (a synchronized Set): ... private Set contexts = Collections.synchronizedSet( new HashSet()); ... public void shutdown() { //notify all the contexts associated to this monitored session synchronized (contexts){ Iterator i = contexts.iterator(); while (i.hasNext()) { ServletContext context = (ServletContext) i.next(); notifySessionShutdown(session, context); ... As part of notifySessionShutdown(), it wants to grab the lock for the SessionMonitors (a plain HashMap): ... private static void notifySessionShutdown( final HttpSession session, final ServletContext context) { SessionDispatcher sessionDispatcher = lookupSessionDispatcher(context); if (sessionDispatcher != null ) { sessionDispatcher.notifySessionShutdown(session); synchronized (SessionMonitors) { ... In thread '35', we see that it grabbed the lock for the SessionMonitors: protected void checkSession(HttpSession session) throws SessionExpiredException { try { final String id = getId(session); final Monitor monitor; synchronized (SessionMonitors) { if (!SessionMonitors.containsKey(id)) { monitor = new Monitor(id, session); SessionMonitors.put(id, monitor); } else { monitor = (Monitor) SessionMonitors.get(id); } //it is possible to have multiple web-app contexts associated with the same session ID monitor.addInSessionContext(context); But as part of calling addInSessionContext(), it needs the lock on the contexts (a synchronized Set) instance being held by thread '49': public void addInSessionContext(ServletContext context) { contexts.add(context); } Subsequent request threads just start piling up waiting on the lock for the SessionMonitors: "[ACTIVE] ExecuteThread: '51' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaadc214000 nid=0x77e9 waiting for monitor entry [0x000000004b336000] java.lang.Thread.State: BLOCKED (on object monitor) at com.icesoft.faces.webapp.http.servlet.SessionDispatcher.checkSession(SessionDispatcher.java:135) - waiting to lock <0x00000004e1dd64c0> (a java.util.HashMap)
        Hide
        Deryk Sinotte added a comment -

        It would appear that this is a regression from the fix for ICE-9242.

        Show
        Deryk Sinotte added a comment - It would appear that this is a regression from the fix for ICE-9242 .
        Hide
        Deryk Sinotte added a comment -

        The changes in ICE-8833 may also have had an impact as they changed when the the sessionMonitor.shutdown() call was made. It now occurs immediately rather than wait for the view to be released at the end of the lifecycle.

        Show
        Deryk Sinotte added a comment - The changes in ICE-8833 may also have had an impact as they changed when the the sessionMonitor.shutdown() call was made. It now occurs immediately rather than wait for the view to be released at the end of the lifecycle.
        Hide
        Deryk Sinotte added a comment -

        A couple of approaches to fixing this. One is to institute a lock ordering to ensure we grab the appropriate lock first. This would entail grabbing the SessionMonitors lock before the context lock when shutting down:

        public void shutdown() {
            //notify all the contexts associated to this monitored session
            synchronized (SessionMonitors){
                synchronized (contexts){
        
                Iterator i = contexts.iterator();

        However this adds additional overhead. Mircea suggested what is likely a better way. Moving the call to addInSessionContext() outside of the block synchronized on SessionMonitors:

        synchronized (SessionMonitors) {
            if (!SessionMonitors.containsKey(id)) {
                monitor = new Monitor(id, session);
                SessionMonitors.put(id, monitor);
            } else {
                monitor = (Monitor) SessionMonitors.get(id);
            }
        }
        //it is possible to have multiple web-app contexts associated with the same session ID
        monitor.addInSessionContext(context);

        This removes the interleaving while reducing (rather than expanding) our synchronization footprint. So I'm going with the second one.

        Show
        Deryk Sinotte added a comment - A couple of approaches to fixing this. One is to institute a lock ordering to ensure we grab the appropriate lock first. This would entail grabbing the SessionMonitors lock before the context lock when shutting down: public void shutdown() { //notify all the contexts associated to this monitored session synchronized (SessionMonitors){ synchronized (contexts){ Iterator i = contexts.iterator(); However this adds additional overhead. Mircea suggested what is likely a better way. Moving the call to addInSessionContext() outside of the block synchronized on SessionMonitors: synchronized (SessionMonitors) { if (!SessionMonitors.containsKey(id)) { monitor = new Monitor(id, session); SessionMonitors.put(id, monitor); } else { monitor = (Monitor) SessionMonitors.get(id); } } //it is possible to have multiple web-app contexts associated with the same session ID monitor.addInSessionContext(context); This removes the interleaving while reducing (rather than expanding) our synchronization footprint. So I'm going with the second one.
        Hide
        Arran Mccullough added a comment -

        New thread dump for recent issue.

        Show
        Arran Mccullough added a comment - New thread dump for recent issue.
        Hide
        Deryk Sinotte added a comment -

        Looks like the original idea of lock ordering would have been the better choice and this is what the customer patch does. Our original fix did solve the immediate problem - a deadlock on checkSession() - but it just left another point where the locks interleaved. So I've gone over the thread dump and the code and added in the lock ordering pretty much as outlined in the client's suggested patch.

        I think the performance hit should be minimal and synchronizing in the catch block, while unorthodox, seems to be okay considering that the catch block is being used to simply catch when an operation on the session is invalid because the session has expired, necessitating that it be safely removed anyway.

        Committed to trunk as revision 38803.

        Show
        Deryk Sinotte added a comment - Looks like the original idea of lock ordering would have been the better choice and this is what the customer patch does. Our original fix did solve the immediate problem - a deadlock on checkSession() - but it just left another point where the locks interleaved. So I've gone over the thread dump and the code and added in the lock ordering pretty much as outlined in the client's suggested patch. I think the performance hit should be minimal and synchronizing in the catch block, while unorthodox, seems to be okay considering that the catch block is being used to simply catch when an operation on the session is invalid because the session has expired, necessitating that it be safely removed anyway. Committed to trunk as revision 38803.
        Hide
        Deryk Sinotte added a comment -

        Patch as applied to trunk

        Show
        Deryk Sinotte added a comment - Patch as applied to trunk
        Hide
        Deryk Sinotte added a comment -

        Customer patch applied. Resolving as fixed.

        Show
        Deryk Sinotte added a comment - Customer patch applied. Resolving as fixed.
        Hide
        Liana Munroe added a comment -

        Verified session expiry on WebLogic8.1 (facelets), JBoss5.1 (jsp), WebLogic12.1.3, glassfish 3.1.2, tomcat 7 (facelets-enh) with component-showcase in IE11, FF34, Chrome43.
        Verified session expiry with concurrent users WebLogic8.1, WebLogic 12.1.3 with component-showcase (facelets).

        Show
        Liana Munroe added a comment - Verified session expiry on WebLogic8.1 (facelets), JBoss5.1 (jsp), WebLogic12.1.3, glassfish 3.1.2, tomcat 7 (facelets-enh) with component-showcase in IE11, FF34, Chrome43. Verified session expiry with concurrent users WebLogic8.1, WebLogic 12.1.3 with component-showcase (facelets).

          People

          • Assignee:
            Deryk Sinotte
            Reporter:
            Deryk Sinotte
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: