[BetaBuild] Having trouble with maintaining conversational context in AS 7.1.0.Beta1

[rmallred]

Okay so I'm having some very strange issues that I believe are related to the container maintaining conversation context incorrectly with an application that I'm currently developing.  We are shooting for JBoss EAP 6 for production when it's all said and done, but for now we are just working our way through the AS 7 releases as they come out.  After making the jump from JBoss AS 7.0.0.FINAL to JBoss AS 7.1.0.Beta1, all of the ajax functionality that previously worked fine no longer functioned correctly without any visible error messages, stack traces in logs etc, literally nothing.  It appears that after each ajax call AS7 is throwing back a NonExistentConversationException via the xml ajax reponse (See Below) which is then getting swallowed, hence why there are no visible errors on the screen, not sure why I wouldn't get a stack trace in the log though.

<partial-response>
     <error>
          <error-name>class org.jboss.weld.context.NonexistentConversationException</error-name>
          <error-message>WELD-000321 No conversation found to restore for id 1</error-message>
     </error>
     <changes>
          <extension primefacesCallbackParam="validationFailed">{"validationFailed":false}</extension>
     </changes>
</partial-response>

The weird part is that I can deploy the exact same .war file onto the two different versions of AS7 and on 7.0.0.Final it functions properly and 7.1.0.Beta1, it doesn't work at all.  My best guess is that the container is no longer maintaining our conversational state correctly, but I have no idea why this would be the case.  Here is my code for opening a new conversation:

Excerpt from mainLookup.xhtml

<ui:define name="additionalHeaderInfo">

        ....

        <f:metadata>
            <f:event 
               listener="#{typeYearMakeModelBean.setUpConvo}"
               type="preRenderView"/>
        </f:metadata>
</ui:define>

Excerpt from typeYearMakeModelBean

private void setUpConvo() {
        if (logger.isDebugEnabled()) {
            logger.debug("TypeYearMakeModelBean.setUpConvo()");
        }
        // Only start a new conversation one doesn't already exist
        if (conversation.isTransient()) {
            conversation.begin();    
            conversation.setTimeout(CONVERSATION_TIMEOUT);
            if(logger.isDebugEnabled())
                logger.debug("Conversation Id: " + conversation.getId() + " Timeout " + conversation.getTimeout());

        }
    }

For reference, here is an example of a JSF component on my page that has embedded ajax behavior that no longer functions

<div class="lookup">
        <h:outputLabel 
            id="typeLabel" 
            for="typeSOL" 
            value="#{msg['epcfe.tymmlookup.outputlabel.type']}" />
        <br/>
        <h:selectOneListbox 
            converter="entityConverter" 
            id="typeSOL" 
            size="1"
            value="#{typeYearMakeModelBean.type}" 
            required="false">
            <f:selectItem 
                itemLabel="#{msg['epcfe.tymmlookup.selectitem.itemlabel.defaultall']}" 
                itemValue="#{null}"
                noSelectionOption="true" />
            <f:selectItems 
                id="typeSIs" 
                value="#{typeYearMakeModelBean.typeList}"
                var="type" itemValue="#{type}"
                itemLabel="#{type.vehicleTypeGroupName}" 
                itemLabelEscaped="true" />
            <p:ajax event="change"
                listener="#{typeYearMakeModelBean.onTypeChange}"
                update="vehicle-nav centerArea" />
        </h:selectOneListbox>
</div>

...and it's backing bean method

public void onTypeChange() {
        if (logger.isDebugEnabled()) {
            logger.debug("TypeYearMakeModelBean.onTypeChange()");
        }
        vehicleTypeChangeEvent.fire(new VehicleTypeChangeEvent(this.type));
        updateListValues(false);
    }

Am I missing something?  Any help would be greatly appreciated.  Also, feel free to request any other relevant bits of code that I may have left out.

-----------------------------------------------------------------------------------------------------------------------------------------

    For reference here is our full technology stack (ommited things I didn't think are relevant, if you think something is missing just ask):

    JBoss AS 7.1.0.Beta1

    Primefaces 3.0.M2

    Mojarra 2.1.3

    Weld 1.1.2.Final

[nickarls]

Strange. Since you get a specific conversation that can't be restored it means the cid was propagated correctly and the conversation was non-transient at the end of the previous jsf lifecycle. So you would probably have to debug Weld in order to see why conversation 1 expires/disappears before the next restore...

[rmallred]

Okay, I guess that's somewhat good news.  Do you think this is a bug in WELD then?  Also, being not as familiar with WELD and it's structure, any tips/helpful resources on going about debugging to determine why the conversation is expiring/disappearing?

[nickarls]

I don't think it is a fundamental flaw in Weld - someone would probably have noticed by now ;-) It could be something with RF or Ajax and the JSF lifecycle. Not that it explains the different behaviour between AS versions. You might want to check out the Weld core impl and place brakepoints in

https://github.com/weld/core/blob/master/impl/src/main/java/org/jboss/weld/context/AbstractConversationContext.java

around activate/deactivate/invalidate in order to see what really happens to the conversation.

Also, you might want to try some simple non-ajax conversational example and compare the behaviour on the two versions

[rmallred]

Thanks for the link, I agree, most likely this is my problem, but the idea of having someone else to blame was quite enticing! 

I haven't had a chance to try stepping through the source for Weld yet, but I did poke around in the file you pointed me to just to see what had changed between 1.1.2 and 1.1.4 and I noticed this JIRA (https://issues.jboss.org/browse/WELD-865) with some mentions to having concurrent calls to a conversation, but no explanation on what type of setup would cause this.  I don't have any real hard evidence this is my problem, but it sounds close. I'm just wondering if it's possible that I could be "recreating" (for lack of a better word) this bug and now that it's fixed in Weld I'm running into my issue. 

Also, I will post back once I have results from your other suggestions around debugging through AbstractConversationContext.java. 

Thanks for the help!

[rmallred]

Okay so it looks like whenever this activate method gets called in AbstractConversationContext....

public void activate(String cid) {
        if (getBeanStore() == null) {
            if (!isAssociated()) {
                throw new IllegalStateException("Must call associate() before calling activate()");
            }
            // Activate the context
            super.setActive(true);

            // Attach the conversation
            if (cid != null) {
                ManagedConversation conversation = getConversation(cid);
                if (conversation != null) {
                    boolean lock = conversation.lock(getConcurrentAccessTimeout());
                    if (lock) {
                        associateRequest(cid);
                    } else {
                        // Associate the request with a new transient conversation
                        associateRequest();
                        throw new BusyConversationException(ConversationMessage.CONVERSATION_LOCK_TIMEDOUT, cid);
                    }
                } else {
                    // CDI 6.7.4 we must activate a new transient conversation before we throw the exception
                    associateRequest();
                    // Make sure that the conversation already exists
                    throw new NonexistentConversationException(NO_CONVERSATION_FOUND_TO_RESTORE, cid);
                }
            } else {
                associateRequest();
            }
        } else {
            throw new IllegalStateException("Context is already active");
        }
    }

when I get to the line where getConversation(cid) is called it is returning a null conversation, even on the initial page load.  I'm pretty sure this is where the "NonExistentConversationException" is getting thrown from after it falls into the else from if(conversation !=null).  It appears that my conversation is never getting added to the conversationMap (I can see now it is getting placed on the map) either no longer in the conversationMap or I have a completely different conversationMap all together.  Any thoughts?

Message was edited by: Richard Allred

[nickarls]

Hmm. The conversation map exists in the session (and also as request attr, not sure why) but I have a hard time believing that the lifecycle could be so messed up that the conversation map would somehow be the "wrong one" - since there should be only one (but it might be worth checking for the object id of the map in the debugger and make sure it goes in the session at the end of the lifecycle). Does it work for a full (non-ajax) request? Only transient conversations should be cleaned out, can you crank logging up to debug and see if it's being cleaned out as transient? Or place debugs in the cleanup sections?

[rmallred]

From what I can tell, I'm having the same issues with non-ajax requests as well, I can't see any difference between the two except that the NonExistentConversationException actually renders as an error on the page for the non-ajax request.  I think the issue is that when the WeldListener calls associate from the requestInitialized method that it's trying to retrieve the conversation map from the session and it isn't there any more, or at least it is never finding it with the CONVERSATIONS_ATTRIBUTE_NAME, but from what I can tell it's the same name that was used to place it on the session on the inital page load.

public boolean associate(R request) {
        if (getRequestAttribute(request, IDENTIFIER) == null) {
            this.associated.set(request);
            /*
            * We need to delay attaching the bean store until activate() is called
            * so that we can attach the correct conversation id
            */
            // Don't reassociate
            setRequestAttribute(request, IDENTIFIER, IDENTIFIER);

            /*
            * We may need access to the conversation id generator and
            * conversations. If the session already exists, we can load it from
            * there, otherwise we can create a new conversation id generator and
            * conversations collection. If the the session exists when the request
            * is dissociated, then we store them in the session then.
            *
            * We always store the generator and conversation map in the request
            * for temporary usage.
            */
            if (getSessionAttribute(request, CONVERSATION_ID_GENERATOR_ATTRIBUTE_NAME, false) == null) {
                ConversationIdGenerator generator = new ConversationIdGenerator();
                setRequestAttribute(request, CONVERSATION_ID_GENERATOR_ATTRIBUTE_NAME, generator);
                setSessionAttribute(request, CONVERSATION_ID_GENERATOR_ATTRIBUTE_NAME, generator, false);
            } else {
                setRequestAttribute(request, CONVERSATION_ID_GENERATOR_ATTRIBUTE_NAME, getSessionAttribute(request, CONVERSATION_ID_GENERATOR_ATTRIBUTE_NAME, true));
            }

            if (getSessionAttribute(request, CONVERSATIONS_ATTRIBUTE_NAME, false) == null) {
                Map<String, ManagedConversation> conversations = new HashMap<String, ManagedConversation>();
                setRequestAttribute(request, CONVERSATIONS_ATTRIBUTE_NAME, conversations);
                setSessionAttribute(request, CONVERSATIONS_ATTRIBUTE_NAME, conversations, false);
            } else {
                setRequestAttribute(request, CONVERSATIONS_ATTRIBUTE_NAME, getSessionAttribute(request, CONVERSATIONS_ATTRIBUTE_NAME, true));
            }

            return true;
        } else {
            return false;
        }
    }

Correct me if I'm wrong but getSessionAttribute(request, CONVERSATION_ID_GENERATOR_ATTRIBUTE_NAME, false) and getSessionAttribute(request, CONVERSATIONS_ATTRIBUTE_NAME, false) shouldn't be null in subsequent requests, after the initial page load correct?  In my case both of them are...

Also, I don't think it's getting cleaned up as transient at least when the first page load happens and it hits the deactivate method

 @Override
    public void deactivate() {
        // Disassociate from the current conversation
        if (getBeanStore() != null) {
            if (!isAssociated()) {
                throw new IllegalStateException("Must call associate() before calling deactivate()");
            }

            if (getCurrentConversation().isTransient()) {
                destroy();
            } else {
                try {
                    // Update the conversation timestamp
                    getCurrentConversation().touch();
                    if (!getBeanStore().isAttached()) {
                        /*
                        * This was a transient conversation at the beginning of the
                        * request, so we need to update the CID it uses, and attach
                        * it. We also add it to the conversations the session knows
                        * about.
                        */
                        if (!(getRequestAttribute(getRequest(), ConversationNamingScheme.PARAMETER_NAME) instanceof ConversationNamingScheme)) {
                            throw new IllegalStateException("Unable to find ConversationNamingScheme in the request, this conversation wasn't transient at the start of the request");
                        }
                        ((ConversationNamingScheme) getRequestAttribute(getRequest(), ConversationNamingScheme.PARAMETER_NAME)).setCid(getCurrentConversation().getId());

                        getBeanStore().attach();

                        getConversationMap().put(getCurrentConversation().getId(), getCurrentConversation());
                    }
                } finally {
                    getCurrentConversation().unlock();
                }
            }
            setBeanStore(null);
            // Clean up any expired conversations
            Iterator<Entry<String, ManagedConversation>> entryIterator = getConversationMap().entrySet().iterator();
            while (entryIterator.hasNext()) {
                Entry<String, ManagedConversation> entry = entryIterator.next();
                if (entry.getValue().isTransient()) {
                    destroyConversation(getSessionFromRequest(getRequest(), false), entry.getKey());
                    entryIterator.remove();
                }
            }
            // deactivate the context
            super.setActive(false);
        } else {
            throw new IllegalStateException("Context is not active");
        }
    }

I fall into the else when I hit the conversation.isTransient if block, and when the while loop iterates over all the conversations it doesn't destroy it there.  So as far as I can tell it's getting put into the map with id '1' correctly.

Feel like I'm spinning my wheels here, but I really appreciate your help.  Hopefully I can track this pesky little bug down soon.

Thanks again!

[rmallred]

Another relevant bit of information that I just deduced and I'm not sure if this is caused by our issue or is a relevant symptom, but after installing a JSF lifecycle phase listener to see if I could tell which phase of the JSF lifecycle we are having troubles with, it doesn't appear that we are entering the JSF lifecycle at all when any type of request is fired. I suppose this could point to a more serious issue, although I'm not really sure.

[nickarls]

Strange. Start from scratch with a fresh project, plain JSF. Make a @ConversationScoped bean with some data and an input field for it. Make a single page that has a button for beginning a non-transient conversation. Add a dummy method that just redirects back to the page. Can you make the conversation stick?

[rmallred]

Okay, sorry it took me so long to get back to you, busy weekend...

So I tried to replicate our problem with a simple app as you suggested, but I just couldn't do it.  No matter what I did, everything with the conversations and WELD seemed to be in order and operating appropriately.  So I moved back to trying to find the problem in our code.  Then I noticed something really strange, if I used my simple test page as the welcome page for our application and just placed a link to the actual main page on it, then just by clicking through the test page first then landing on our page all of our conversations would work correctly.  This was true even after refreshes on the "real" homepage and the click-through was only necessary on the first page load after a redeploy. I still have no explanation for this.

I have continued to poke around and add and remove different pieces of our homepage trying to isolate the culprit that is breaking our conversations.  The weird part was I could take one of our components off the page and then everything would start working, and then remove a different component, and add back the original component that I had removed, that I had assumed as the problem and the conversations would still function correctly.  It got to the point where it seemed like it really only matter that I removed one of our components, which one was irrelevant.  Then I began to wonder if the amount of "conversationally scoped" components or the amount of beans that backs them could possibly be the problem.  I then discovered that if I took one of the beans that was backing an input component on our page that was @ConversationScoped and changed the annotation to @SessionScoped then our app functioned normally again.  So I'm wondering is it possible that we have reached some upper limit of conversationally scoped beans? This combined with the click-through page approach I mentioned above makes me think that our conversation is getting created correctly but because there are so many things on the page that have to get associated with said conversation once all of that processing is done the original conversation created in the "preRenderViewEvent" is no longer around. However, from what I can tell however WELD is never "expiring" or "destroying" our conversation (or at least the breakpoints I have in those methods are never getting touched).

I know this doesn't make a lot of sense, but it's the only thing I can think of that explains why I can add and remove seemily random bits of our code to remedy our conversation issue. 

Let me know what you think, and again I am very grateful for your help with this!

[nickarls]

Are you using facelets? And you are using the same @ConversationScoped annotation everywhere, right? (OK, JSF doesn't have one so it's hard to get wrong by accident). There should be no theorethical maximum. Does the page load quickly? Just a hunch - have you tried placing a breakpoint in the Weld lifecycle (AbstractConversationContext?) where concurrent access is handled? In case there is some timeout in trying to access the conversation that kills them (they are locked from concurrent access and have a wait-timeout). One one think that would bomb out with an exception, though...

[rmallred]

Yes we are using facelets, and we are only using javax.enterprise.context.ConversationScoped for the @ConversationScoped.  The page doesn't load particularly slow, but it's definitely not blazing fast either.  One thing to note is that we do have some dropdowns and select boxes that have ALOT of options (I'm talking like 16,000 in the worst case).  Also this app was design to be almost entirely one page with primarily ajax behavior on most of our components.  We currently have about 13 different @ConversationScoped backing beans for different components on the page.  Granted not all of these components are rendered on the initial state of the homepage.

I have debugged through AbstractConversationContext many times, and I have never seen it fall into the concurrent access case (and from what I can tell you're right a BusyConversationException should be thrown).  The only thing that seems amiss in AbstractConversationContext is that when it tries to look up our conversation via the CONVERSATIONS_ATTRIBUTE_NAME during the call to assosciate it's no longer attached to the session for whatever reason.


[gustavopollitzer]

Hello! How are you?

I have exactly the same problem. But my page is light, I am using JBoss 7.1.1.Final (Brontes), and PrimeFaces 3.4.2

The problem occurs in the first post of a page that was reached from the index.html page by means of <meta http-equiv="Refresh" content="0; URL=thePage.jsf">

If I reload the page after the error, everithing works fine. Apparently, the conversations map is cleaned in some point between the first and the second JSF lifecycles. The first one only traverses the restore view and render response phaces. And the second one throws "org.jboss.weld.context.NonexistentConversationException: WELD-000321 No conversation found to restore for id 1" in the beggining of the second lifecycle. Exactly like Richard's application.

Richard, did you solve the issue?