Active View Maps - LRU Map - Gets Corrupted - Likely Because of Restore View State

[99sono]

Hi,

I have recently been given to analyse a heap dump where essentially one thread went forever on an endless cycle trying to process the expire sessions logic.

Something like this, running up to eternity:

java.lang.Thread.State: RUNNABLE
at java.util.concurrent.ConcurrentHashMap.hash(ConcurrentHashMap.java:333)
at java.util.concurrent.ConcurrentHashMap.containsKey(ConcurrentHashMap.java:1016)
at com.sun.faces.mgbean.BeanManager.isManaged(BeanManager.java:201)
at com.sun.faces.application.view.ViewScopeManager.destroyBeans(ViewScopeManager.java:138)
at com.sun.faces.application.view.ViewScopeManager.sessionDestroyed(ViewScopeManager.java:296)
at com.sun.faces.application.WebappLifecycleListener.sessionDestroyed(WebappLifecycleListener.java:169)
at com.sun.faces.config.ConfigureListener.sessionDestroyed(ConfigureListener.java:373)
at org.apache.catalina.session.StandardSession.expire(StandardSession.java:807)
- locked <2973a5c9> (a org.apache.catalina.session.StandardSession)
at org.apache.catalina.session.StandardSession.expire(StandardSession.java:769)
at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:686)
at org.apache.catalina.session.StandardSession.getAttribute(StandardSession.java:1225)


After analysing the heap dump, I was eventually able to discover the ACTIVE_VIEWS LRU Map was corrupted.

@Override public void sessionDestroyed(HttpSessionEvent hse) { if (LOGGER.isLoggable(Level.FINEST)) { LOGGER.log(Level.FINEST, "Cleaning up session for @ViewScoped beans"); }

    HttpSession session = hse.getSession();
    Map<String, Object> activeViewMaps = (Map<String, Object>) session.getAttribute(ACTIVE_VIEW_MAPS);
    if (activeViewMaps != null) {
        Iterator<Object> activeViewMapsIterator = activeViewMaps.values().iterator();  <--------------------- This iterator loop never finished

        ApplicationAssociate applicationAssociate = ApplicationAssociate.getInstance(hse.getSession().getServletContext());
        while (activeViewMapsIterator.hasNext()) {
            Map<String, Object> viewMap = (Map<String, Object>) activeViewMapsIterator.next();
            destroyBeans(applicationAssociate, viewMap);
        }

        activeViewMaps.clear();
        session.removeAttribute(ACTIVE_VIEW_MAPS);
        session.removeAttribute(ACTIVE_VIEW_MAPS_SIZE);
    }
}

I looked at the JDK implementation of the Linked Hash Map to see if there was any logical error in the iterator or on how the linked hash map builds up its Header linked list, and the map is sound and solid.

The Heap Dump revealed that essentialls the active View map in the underlying HashMap which is extended by the LinkedHashMap was respective the buffer size of 25 entries.
There should only have been 25 entries to iterate over.
However, though the base HashMap was sound the Linked HashMap header structure that is updated by the interal "inserBefore" metho was totally corrupted.

In particular, navigating from header->after->after as the Iterator would do would lead to an infinite cycle between three entries. This is completely wrong, as it is clear in the Interator logic that the linked hash map should be of the form:

Header->After->After->Afeter ->....Header
The structure should circle back around to the begining.

And in fact, the LRU map of JSF nicely respected this invariant if you navigated it down for the Before relationshop you see.
Header->Before->Before->Before-> .... -> Header

This means, had the iterator in the LRU linked hash map in the case of this infinite cycle been created from newest entry to the oldest, the loop would have actually finished.

The Head Dump in addition reveleade that one of the Entries in the LRU Linked hash map had
entry->after element that did not correspond to the after->before element.

In short, the LRU linked hash map was 100% corrupted.

I was not able to find blame neither in the JDK linked hash map implementatino nor in the ViewScopeManager, which on the method called

private void processPostConstructViewMap(SystemEvent se)

Uses proper synchronization primitives to modify the resource:

Map viewMaps = (Map) sessionMap.get(ACTIVE_VIEW_MAPS); synchronized (viewMaps) { ------------------- This is OK as the not thread safe ViewMaps is being being accessed in a proper synchronization block

                String viewMapId = UUID.randomUUID().toString();
                while (viewMaps.containsKey(viewMapId)) {
                    viewMapId = UUID.randomUUID().toString();
                }

                if (viewMaps.size() == size) {
                    String eldestViewMapId = viewMaps.keySet().iterator().next();
                    Map<String, Object> eldestViewMap = (Map<String, Object>) viewMaps.remove(eldestViewMapId);
                    removeEldestViewMap(facesContext, eldestViewMap);
                }

                viewMaps.put(viewMapId, viewMap);
                viewRoot.getTransientStateHelper().putTransient(VIEW_MAP_ID, viewMapId);
                viewRoot.getTransientStateHelper().putTransient(VIEW_MAP, viewMap);
            }

Finally, I decided to search futher and I found the following code that I am for the most part convinced is at the heart of corrupting this map and leading to the infinite cycle:

UIViewRootComponent:

@Override
public void restoreState(FacesContext context, Object state) {

    if (context == null) {
        throw new NullPointerException();
    }
    if (state == null) {
        return;
    }

    values = (Object[]) state;

    if (!context.getAttributes().containsKey("com.sun.faces.application.view.restoreViewScopeOnly")) {
        super.restoreState(context, values[0]);
    }

    String viewMapId = (String) values[1];

    getTransientStateHelper().putTransient("com.sun.faces.application.view.viewMapId", viewMapId);

    Map<String, Object> viewMaps = (Map<String, Object>) context.getExternalContext().
            getSessionMap().get("com.sun.faces.application.view.activeViewMaps");  <----------------------- (1) First this code is not nice as it should be using the proper constants that are already defined in ViewScopeManager.java class and publicly accessible - Hard coding the string in this file is not a good idea

    if (viewMaps != null) {
        Map<String, Object> viewMap = (Map<String, Object>) viewMaps.get(viewMapId); <--------------------- (2) This code looks to me 100% wrong. You cannot do a get in AN LRU map that is not thread safe without first ensuring that nobody else accesses the map. 



        getTransientStateHelper().putTransient("com.sun.faces.application.view.viewMap", viewMap);
    }
}

This code should be doing exactly the same thing as the ViewScopeManager with a synchronizes(viewMaps)
The error is of course not deterministic and not easy to reproduce. However, nowhere in our code do we play around with internal Session manager maps of the JSF framework and therefore the LRU map corruption must be coming from within the JSF reference implementation itself.

As I do not want to patch our code with the assumpation that when glassfish kills a session we may just get a thread stuck forever consuming CPU cycles, I will be modify that 2.1.25 UIViewRootComponent to try to get the problem patched.

I would appreciate your feedback on this.

I've taken a look 2.1.29 and the bug seems to be there as well.

Kindest regards,
Nuno.