seam or richfaces losing view state param

[deanhiller2000]

How can seam give a conversation timeout in 9 ms with never calling into my beans...soooo odd.

I think there is a seam or richfaces race condition or something.  In production, once in every 100 requests or so, the post does not have the view state which then for some reason causes the typical conversation timeout(we have run the SAME exact script manually and seen the issue without changing the way we go through the script).

We click next button on each page.  Here is a log from the previous page and the page that failed(notice the view state is missing from the thrid log line).  Also, we keep displaying page.xhtml while they hit the next button but the context is different every time so essentially the 3rd log and 1st log below should match nearly exactly except one had a radio button and one had another type of gui widget.

2010-10-29 00:49:18,339 INFO  [net.voicelog.web.http.LogHttpReqFilter.ajax] (http-0.0.0.0-8080-3) [player][session:l2rw__,c:,r:136] ajax url=(POST)http://xxxxx:8080/scripts/secure/client/scripter/agent/page.xhtml params={AJAXREQUEST=sync,questionForm:inputTable:0:nameDecorate:namec=on,questionForm:errorDecorator:placeForErrors=Hidden field,questionForm:faqPanelOpenedState=,questionForm=questionForm,autoScroll=,javax.faces.ViewState=j_id13,questionForm:movenext=questionForm:movenext,}
button clicked=questionForm:movenext

<LOTS OF BEAN METHOD CALLS IN BETWEEN HERE>

2010-10-29 00:49:18,435 INFO  [net.voicelog.web.http.LogHttpReqFilter.ajax.timing] (http-0.0.0.0-8080-3) [player][session:l2rw__,c:,r:136] [time(ms):96] finished sending url=(POST)http://xxxxx:8080/scripts/secure/client/scripter/agent/page.xhtml

<There is a GET request here and sql calls to db to load next page>

2010-10-29 00:49:23,441 INFO  [net.voicelog.web.http.LogHttpReqFilter.ajax] (http-0.0.0.0-8080-7) [player][session:l2rw__,c:,r:138] ajax url=(POST)http://xxxxx:8080/scripts/secure/client/scripter/agent/page.xhtml params={AJAXREQUEST=sync,questionForm:inputTable:0:yesNoDecorate:yesNoRadio=true,questionForm:errorDecorator:placeForErrors=Hidden field,questionForm:faqPanelOpenedState=,questionForm:movenext=questionForm:movenext,}
button clicked=questionForm:movenext

<NO METHOD BEAN CALLS AND ONLY 9 ms apart>

2010-10-29 00:49:23,450 INFO  [net.voicelog.web.http.LogHttpReqFilter.ajax.timing] (http-0.0.0.0-8080-7) [player][session:l2rw__,c:,r:138] [time(ms):9] finished sending url=(POST)http://xxxxx:8080/scripts/secure/client/scripter/agent/page.xhtml

I also log the POST returns and between the logs of the first one, I can see it calling into my beans.  On the second POST, it is locked from a seam lock or something or at least never calls into my beans and then 9 milliseconds later returns.

More oddly, here is my components.xml(and yes, those values are too hight to be honest and should be more like 3 seconds....we had some stuff under seam-storedproc-taking 10 seconds holding seam locks making seam fail when we didn't want that...the 30 second fixed it temporarily as a stop gap quick fix until we come back to that issue).

components.xml...

    <core:manager conversation-timeout="900000" 
                  concurrent-request-timeout="30000"
                  conversation-id-parameter="cid"/>

[deanhiller2000]

I also noticed in the above logs that these two are missing from the 2nd post request as well

questionForm=questionForm,
autoScroll=

so the hidden input element for the form is missing(I wonder why JSF puts that in there..doesn't seem to have any info ever).

It is so weird, this happens around once in a hundred times.  some kind of framework race condition caused by the ajax stuff...almost wish I wasn't doing ajax or was doing complete GWT at this point.

Dean

[deanhiller2000]

I didn't get any farther yet so I added javascript to pop a window up with the input element with id javax.faces.ViewState is missing to tell the user hit the back button and click next and that we are still investigating that bug and added logs to production as I don't know this occurs yet but suspect the previous get response was missing that critical hidden field for some reason(maybe richfaces didn't render it or something)....too bad this only happens once every month or so though.

[kragoth]

Hi Dean,

I want to confirm a few things with you about this problem. I am experiencing what I think is a related issue in my application.

What browser are you using? (Have you tested on any others)
What server are you using? (I'm using tomcat 6)

I'm going to try and explain the problem I am having in hope that the more information we can pool together the closer to a solution (or at least a reason) we can get. Please brace yourselves for some of the weirdest programming moments in history. :P

I have a fairly simple page that contains a couple of date pickers and a couple of drop down menus (comboBoxes). (<rich:comboBox> essentially, but they are our own tags that are direct subclasses of the richfaces tags with some CSS guff etc. Nothing fancy.)

So, now the problem itself.

When the error occurs (after a button is pushed) JSF bails out after Phase 1 (restore view) and takes me to an error page. The reason it bails out after Phase 1 and goes straight to Phase 6 (render response) is because of this line in the RestoreViewPhase.java

boolean isPostBack = (isPostback(facesContext) && !isErrorPage(facesContext));

The isPostback method essentially does this

public static final String VIEW_STATE_PARAM = "javax.faces.ViewState";
@Override
public boolean isPostback(FacesContext context) {
    return 
        context.getExternalContext().getRequestParameterMap().
            containsKey(ResponseStateManager.VIEW_STATE_PARAM);
}

So...it is looking for the ViewState param in the requestParams Map and not finding it.

So..cutting a long story short, the view is rerendered but because Seam was unable to work out what conversation it was in due to lack of required params in the map my app dies a horrible death due to variables being null etc that really shouldn't be.

I've put a good amount of time into trying to figure this out so bear with me as I go through what I have tried.

PACKET SNIFFING

Yep, I dropped down to the packet level and compared the http POST packets on a successful POST and a failed POST. They contain exactly the same data (obviously with different packet ids etc). The ViewState param IS IN the POST even on a failure situation.

THE WEIRDNESS FACTOR

OK, what I'm about to say here would make most programmers think I'm crazy...and to be honest I have felt I have been going crazy trying to work this one out.

1. Reproducing the problem.

This problem does NOT always happen. There are certain factors that make it happen more often but there is no case that is 100% failure.

I have found that the best way to get a failure situation is to type the string 33(!) into the drop down menu and press a button. Regardless of the valid options in the drop down menu this combination gave me a fairly consistent failure rate, 80% roughly. Combinations such as 3(!), 34(!), or pretty much any combination of 33(XXX) where XXX is a symbol like $@!*& will all cause a failure. (Are you confused yet? :P) That all being said even a combination like 33 - 11 SL(!) can cause a failure. (This example is the one that actually started my investigation as this is a valid value for one of our drop down menus. The (!) at the end of the value means that it is an inactive option but is still in the list for historical purposes) ALL of these examples were performed in IE6. There are combinations that seem to NEVER cause a failure. (In fact most of my options never cause an error).

So, in an effort to establish some sort of pattern I booted up a machine with IE8 and proceeded to try the same combinations in that browswer. I tested for a few minutes without a single failure. But today I tried again and after about 10 or so clicks I had a failure. So, I thought that I could pretty much rule out that the browser being the problem. But, before we get onto that there's more!

Not willing to give up I tried some more stuff. All our buttons in our application are our own components. These buttons are a straight subclass of the javax.faces.component.html.HtmlCommandLink with some styling to make them look pretty. Very little extra functionality has been added to them. If I remove our buttons and replace them with the standard <h:commandButton> or <h:commandLink> I do NOT get any failures. Starting to look more like a javascript problem now right! :) (I need to so more testing on this to make sure I can't reproduce it with a standard control)

BUT!!!!! What about the packets I talked about earlier. IF this was a javascript problem. Shouldn't I be seeing the problems in the packets?? And why do I only have the problem sometimes. And why does the combination 33(!) fail much much more often then any other combination.

So, Dean.
I'm sorry I don't have any answers for you yet...if anything I have more questions. I need to do a few things like change Tomcat versions and see if it still happens.

But for now, the 33(!) is haunting me and why does changing the combination 33 - 11 SL(!) to 33T - 11 SL(!) stop it from failing.

Anyway, this is about where I'm up to at the moment. I have done some preliminary investigations into what's happening server side early on in the request lifecycle but I haven't found out where the ViewState param is being lost.

I'm probably going to have to give up on this defect for a while as I have higher priorities and I'll just have to tell the users to just try again whenever this happens until I can actually work out what the heck is going on.

If anyone has any ideas I'd be really glad to hear them. :) I'm starting to feel very confused. :P

[deanhiller2000]

nice.  I only see this in production once a month if that until they do more load.  I have since left that company though :( so problem solved...just joking.

I left the problem in the state where I had just added the JSF phase logs to see where it was dropping out.  I have not been able to reproduce the problem in development at all!!!!!!

I hacked some javascript in to check viewstate in the html page itself but looking from your investigation that won't work.  Those poor guys are going to be stuck with this problem :(.

lastly, we don't have any customized tags in our xhtml but it is ajax buttons and ajax based so I think if I went to non-ajax, the problem would be solved.  In fact,, I think that is the solution I would go with on that project (they don't really need the ajax solution though it is pretty nice).

[deanhiller2000]

oh, I cannot reproduce mine in development at all!!! so keep your dev view handy if you can reproduce it pretty consistently as the more your app changes, it may happen way less and then be harder to debug.