Concurrent call to conversation error when unde...| JBoss.org Content Archive (Read Only)

15. Re: Concurrent call to conversation error when under load

rossmills.ross_mills.intuit.com Nov 18, 2009 6:25 PM (in response to rossmills.ross_mills.intuit.com)

Vasilii - Thanks! I'll need to come up to speed on working with dumps, but there are people here who can help me with that. That's a good idea.

Arbi - I agree. The logs don't make sense. I was studying the logs more last night and found one conversation ID was being restored at the rate of about once per second. If there is a ten second delay between pages, and there's not a lot of AJAX components in the app, there should be no way for that to happen.

I suspect something is wrong with the load test. Like you suggested, conversation ids are probably being re-used across sessions. I'll need to confirm or eliminate this possibility before I do anything else. I think I'll create a servlet filter to log the URL, the thread, the session id, the conversationId request parameter and the conversation entries. I suspect that I might find two sessions passing the same conversationId.

What's strange is that these tests worked very well in the past. I'm not sure why they are failing now.

And yes, my seam log is exactly as you described

16. Re: Concurrent call to conversation error when under load

rossmills.ross_mills.intuit.com Nov 18, 2009 11:22 PM (in response to rossmills.ross_mills.intuit.com)

I can reproduce the problem by letting my automated test run with only 1 user. Everything goes fine for the first few minutes. Then after about 10 minutes, I get the concurrent conversation problem.

The test goes like this...
(1) The user clicks a link from the menu. This causes the current conversation to ended. The user is redirected to a search form and a new conversation is started.
(2) The user fills out the form and the user is forwarded (rendered) to the search results.
(3) The user navigates forward, backward and drills down in the search results. All this is done with forwards (renders). No AJAX is involved.
(4) The user then goes back to step (1) by clicking on the menu link again - which ends that conversation and starts a new one.

The script runs through these steps over and over until the problem occurs.

In the logs below, where the conversation entry changes from 57 to 60, is when the user clicks on the menu link to view the search form. The form then sits idle for 12 seconds. After the 12 seconds, the user attempts to submit the form, but encounters the concurrent conversation error.

In the logs generated by the Seam API, it appears that when the form was displayed, thread 16 restored the conversation but never bothered to store it. So when the form was submitted 12 seconds later, thread 21 found the conversation locked and generated the error.

It's looking more and more to me like the problem (at least this one anyway) is somewhere in the Seam API - not in the automated tests.

This is the log generated by my servlet filter...

DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-13]     [2009-11-18 13:23:26]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/resource/remote.js] query=[null] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-16]     [2009-11-18 13:23:27]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/interface.js] query=[remotingAPI] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-18]     [2009-11-18 13:23:27]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReview.jsf] query=[null] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-10]     [2009-11-18 13:23:27]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/resource/remote.js] query=[null] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-1]     [2009-11-18 13:23:27]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/interface.js] query=[remotingAPI] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-17]     [2009-11-18 13:23:28]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReview.jsf] query=[null] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-2]     [2009-11-18 13:23:29]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/resource/remote.js] query=[null] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-19]     [2009-11-18 13:23:29]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/interface.js] query=[remotingAPI] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-4]     [2009-11-18 13:23:29]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReview.jsf] query=[null] cidlist=[ConversationEntries([ConversationEntry(52)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-20]     [2009-11-18 13:23:29]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReviewForm.jsf] query=[null] cidlist=[ConversationEntries([])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-3]     [2009-11-18 13:23:29]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/resource/remote.js] query=[null] cidlist=[ConversationEntries([ConversationEntry(57)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-11]     [2009-11-18 13:23:29]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/interface.js] query=[remotingAPI] cidlist=[ConversationEntries([ConversationEntry(57)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-5]     [2009-11-18 13:23:29]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/echo-theme/images/icons/8x8/required_field.png] query=[null] cidlist=[ConversationEntries([ConversationEntry(57)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-9]     [2009-11-18 13:23:29]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReviewForm.jsf] query=[null] cidlist=[ConversationEntries([ConversationEntry(57)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-7]     [2009-11-18 13:23:30]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/resource/remote.js] query=[null] cidlist=[ConversationEntries([ConversationEntry(57)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-12]     [2009-11-18 13:23:30]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/interface.js] query=[remotingAPI] cidlist=[ConversationEntries([ConversationEntry(57)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-6]     [2009-11-18 13:23:30]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReview.jsf] query=[null] cidlist=[ConversationEntries([ConversationEntry(57)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-14]     [2009-11-18 13:23:30]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReviewForm.jsf] query=[null] cidlist=[ConversationEntries([])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-8]     [2009-11-18 13:23:30]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/resource/remote.js] query=[null] cidlist=[ConversationEntries([ConversationEntry(60)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-15]     [2009-11-18 13:23:30]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/remoting/interface.js] query=[remotingAPI] cidlist=[ConversationEntries([ConversationEntry(60)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-13]     [2009-11-18 13:23:30]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/seam/resource/echo-theme/images/icons/8x8/required_field.png] query=[null] cidlist=[ConversationEntries([ConversationEntry(60)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-16]     [2009-11-18 13:23:30]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReviewForm.jsf] query=[null] cidlist=[ConversationEntries([ConversationEntry(60)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-21]     [2009-11-18 13:23:42]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[null] url=[/bc/restricted/reports/tranReviewForm.jsf] query=[null] cidlist=[ConversationEntries([ConversationEntry(60)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-18]     [2009-11-18 13:23:43]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[62] url=[/bc/restricted/error.jsf] query=[cid=62] cidlist=[ConversationEntries([ConversationEntry(62), ConversationEntry(60)])]
DEBUG     [BusinessCenter.ajp-172.19.217.101-8009-22]     [2009-11-18 13:23:55]     sessionID=[EA72A813AEFE40E6719CC8CA6C55D5AD.bc_node1] cidParm=[62] url=[/bc/restricted/error.jsf] query=[cid=62] cidlist=[ConversationEntries([ConversationEntry(62), ConversationEntry(60)])]

This is the log generated by the Seam API...

DEBUG     [ajp-172.19.217.101-8009-15]     [2009-11-18 13:23:26]     Storing conversation state: 52
DEBUG     [ajp-172.19.217.101-8009-16]     [2009-11-18 13:23:27]     No stored conversation
DEBUG     [ajp-172.19.217.101-8009-16]     [2009-11-18 13:23:27]     Discarding conversation state: 54
DEBUG     [ajp-172.19.217.101-8009-18]     [2009-11-18 13:23:27]     Restoring conversation with id: 52
DEBUG     [ajp-172.19.217.101-8009-18]     [2009-11-18 13:23:27]     Storing conversation state: 52
DEBUG     [ajp-172.19.217.101-8009-1]     [2009-11-18 13:23:27]     No stored conversation
DEBUG     [ajp-172.19.217.101-8009-1]     [2009-11-18 13:23:27]     Discarding conversation state: 55
DEBUG     [ajp-172.19.217.101-8009-17]     [2009-11-18 13:23:28]     Restoring conversation with id: 52
DEBUG     [ajp-172.19.217.101-8009-17]     [2009-11-18 13:23:28]     Storing conversation state: 52
DEBUG     [ajp-172.19.217.101-8009-19]     [2009-11-18 13:23:29]     No stored conversation
DEBUG     [ajp-172.19.217.101-8009-19]     [2009-11-18 13:23:29]     Discarding conversation state: 56
DEBUG     [ajp-172.19.217.101-8009-4]     [2009-11-18 13:23:29]     Restoring conversation with id: 52
DEBUG     [ajp-172.19.217.101-8009-4]     [2009-11-18 13:23:29]     Ending long-running conversation
DEBUG     [ajp-172.19.217.101-8009-4]     [2009-11-18 13:23:29]     Discarding conversation state: 52
DEBUG     [ajp-172.19.217.101-8009-20]     [2009-11-18 13:23:29]     No stored conversation
DEBUG     [ajp-172.19.217.101-8009-20]     [2009-11-18 13:23:29]     Beginning long-running conversation
DEBUG     [ajp-172.19.217.101-8009-20]     [2009-11-18 13:23:29]     Storing conversation state: 57
DEBUG     [ajp-172.19.217.101-8009-11]     [2009-11-18 13:23:29]     No stored conversation
DEBUG     [ajp-172.19.217.101-8009-11]     [2009-11-18 13:23:29]     Discarding conversation state: 58
DEBUG     [ajp-172.19.217.101-8009-9]     [2009-11-18 13:23:29]     Restoring conversation with id: 57
DEBUG     [ajp-172.19.217.101-8009-9]     [2009-11-18 13:23:29]     Storing conversation state: 57
DEBUG     [ajp-172.19.217.101-8009-12]     [2009-11-18 13:23:30]     No stored conversation
DEBUG     [ajp-172.19.217.101-8009-12]     [2009-11-18 13:23:30]     Discarding conversation state: 59
DEBUG     [ajp-172.19.217.101-8009-6]     [2009-11-18 13:23:30]     Restoring conversation with id: 57
DEBUG     [ajp-172.19.217.101-8009-6]     [2009-11-18 13:23:30]     Ending long-running conversation
DEBUG     [ajp-172.19.217.101-8009-6]     [2009-11-18 13:23:30]     Discarding conversation state: 57
DEBUG     [ajp-172.19.217.101-8009-14]     [2009-11-18 13:23:30]     No stored conversation
DEBUG     [ajp-172.19.217.101-8009-14]     [2009-11-18 13:23:30]     Beginning long-running conversation
DEBUG     [ajp-172.19.217.101-8009-14]     [2009-11-18 13:23:30]     Storing conversation state: 60
DEBUG     [ajp-172.19.217.101-8009-15]     [2009-11-18 13:23:30]     No stored conversation
DEBUG     [ajp-172.19.217.101-8009-15]     [2009-11-18 13:23:30]     Discarding conversation state: 61
DEBUG     [ajp-172.19.217.101-8009-16]     [2009-11-18 13:23:30]     Restoring conversation with id: 60
DEBUG     [ajp-172.19.217.101-8009-21]     [2009-11-18 13:23:43]     Concurrent call to conversation

17. Re: Concurrent call to conversation error when under load

asookazian Nov 19, 2009 12:30 AM (in response to rossmills.ross_mills.intuit.com)

Ross Mills wrote on Nov 18, 2009 23:22:

It's looking more and more to me like the problem (at least this one anyway) is somewhere in the Seam API - not in the automated tests.

which is why it's lame that the Seam core devs don't chime in on this thread (or most threads in this Seam forum, for that matter).

open a JIRA for this issue and they'll look at it. remember to attach a zip file of your code to reproduce the problem.

18. Re: Concurrent call to conversation error when under load

rossmills.ross_mills.intuit.com Nov 19, 2009 7:47 PM (in response to rossmills.ross_mills.intuit.com)

From the logs, it appears that when the conversation remains locked, it is because the JSF lifecycle never got beyond the RESTORE VIEW phase. There is no RENDER RESPONSE phase. From the logs, it appears that the JSF lifecycle abruptly halts. There are no error messages. Then, 10 minutes later, when the next request is received, the locked conversation causes the concurrent conversation error to occur.

19. Re: Concurrent call to conversation error when under load

rossmills.ross_mills.intuit.com Nov 19, 2009 8:37 PM (in response to rossmills.ross_mills.intuit.com)

Bug report filed

https://jira.jboss.org/jira/browse/JBSEAM-4480

20. Re: Concurrent call to conversation error when under load

rossmills.ross_mills.intuit.com Nov 20, 2009 9:00 PM (in response to rossmills.ross_mills.intuit.com)

I would like to log what is going on in the JSF implementation. However, I can't seem to configure my jboss-log4j.xml correctly. Does anyone have an example log4j config that successfully generates JSF logs?

I've tried the same approach taken by the poster of this thread but hit the very same problem:

http://seamframework.org/Community/EnableJSFfaceletLoggingInJBoss422

I'm using JBoss 4.2.2.GA

21. Re: Concurrent call to conversation error when under load

rossmills.ross_mills.intuit.com Nov 21, 2009 2:11 AM (in response to rossmills.ross_mills.intuit.com)

Apparently, generating JSF logs cannot be done in JBoss 4.2.2 because of a JBoss bug. The logging problem was fixed in later versions.

I removed the use of long term conversations from the app and replaced redirects with renders. I also changed the scope of my conversational scoped beans to session scope. This made the problem go away. But eliminating the use of long-term conversations is certainly not a satisfactory solution.

I might try testing this out with a newer version of JBoss. But I've already spent waaaay too much time trying to resolve this problem.

22. Re: Concurrent call to conversation error when under load

rossmills.ross_mills.intuit.com Nov 24, 2009 9:28 PM (in response to rossmills.ross_mills.intuit.com)

Our successful run was a fluke. We continued hitting concurrent conversation errors the next time we ran it.

But it looks like we're getting to the bottom of this. Here's an update.

For some reason, from time to time, a JBoss thread would hang for about 25 seconds or so. We're don't know why the thread would hang. But the way we had Apache/modjk configured caused Apache to timeout before the JBoss thread could complete. Apache would timeout and return an error message to the browser. However, the automated test would go ahead and continue onto the next page. When the next request was received by JBoss, the previous request thread was still hung and the conversation was still locked. This caused the concurrent conversation error.

We were able to resolve this by fixing the workers.properties file in Apache. The socket timeout was removed and keepalive was turned back on. This made Apache wait for the JBoss thread to become unhung and complete its lifecycle and unlock the conversation.

The reason we started making changes to Apache in the first place was that we were getting 503 errors when we load tested the app. The reason for that turned out to be a typo in the Tomcat server.xml file. I had spelled maxThreads as maxthreads. That was enough to cause Tomcat to become overwhelmed and start refusing connections. When the typo was fixed, the 503 errors went away.

Soon, I plan on trying the thread dump solution suggested earlier in this thread to figure out why the thread is hanging in the first place.

23. Re: Concurrent call to conversation error when under load

cash1981 Nov 26, 2009 11:35 PM (in response to rossmills.ross_mills.intuit.com)

From what I can see you are using commandLink which will post. Maybe you should switch to s:link and do a get instead of post. Obviously if you push the link a few times fast after eachother, you might get exception.

Get's are quicker to perform.

24. Re: Concurrent call to conversation error when under load

cash1981 Nov 26, 2009 11:47 PM (in response to rossmills.ross_mills.intuit.com)

Arbi Sookazian wrote on Nov 19, 2009 00:30:

which is why it's lame that the Seam core devs don't chime in on this thread (or most threads in this Seam forum, for that matter).

open a JIRA for this issue and they'll look at it. remember to attach a zip file of your code to reproduce the problem.

You should have read my blog Arbi. The seam team will no longer fix any bugs for seam 2, nor will they look at what is filed on JIRA. Ok, they might look, but thats all. However, if you have a support subscription, you will get help.

25. Re: Concurrent call to conversation error when under load

rossmills.ross_mills.intuit.com Nov 30, 2009 8:00 PM (in response to rossmills.ross_mills.intuit.com)

Shervin Asgari wrote on Nov 26, 2009 23:35:

From what I can see you are using commandLink which will post. Maybe you should switch to s:link and do a get instead of post. Obviously if you push the link a few times fast after eachother, you might get exception.

Get's are quicker to perform.

The problem was resolved last week. It had nothing to do with commandLink vs s:link. The reason for the problem was stated in this thread. I apologize if it was not clear.