Loading...

XML

Word

Printable

Details

Type: Bug
Resolution: Won't Do
Priority: Critical
Fix Version/s: None
Affects Version/s: EAP_EWP 5.1.2
Component/s: Seam2
Labels:
None
Environment:

Seam2.2.5.EAP5, EAP6.0.0 ER6, Fedora, both OpenJDK 1.6 and jdk1.6.0_30

Steps to Reproduce:

Hide

Reproducible almost always on my machine

1. unzip the eap5.1.2 distribution
2. edit jboss.home in seam/build.properties
3. Replace the seam/examples directory with the untarred attached sources (seam-2.2-booking-eap6.tar).
4. build the examples/booking example with "ant"
5. deploy the examples/booking/dist/jboss-seam-booking.ear on EAP6
6. go to http://127.0.0.1:8080/seam-booking
7. login as gavin/foobar
8. enter "a" into the search field and wait (don't press or click anything else)
9. notice the error, or logout and try again

Show
Reproducible almost always on my machine 1. unzip the eap5.1.2 distribution 2. edit jboss.home in seam/build.properties 3. Replace the seam/examples directory with the untarred attached sources (seam-2.2-booking-eap6.tar). 4. build the examples/booking example with "ant" 5. deploy the examples/booking/dist/jboss-seam-booking.ear on EAP6 6. go to http://127.0.0.1:8080/seam-booking 7. login as gavin/foobar 8. enter "a" into the search field and wait (don't press or click anything else) 9. notice the error, or logout and try again
Affects:

Release Notes
Workaround:

Workaround Exists
Workaround Description:

Hide

Add @AccessTimeout(0) to the EJB, this means it will throw an ConcurrentAccessException immediately when this situation occurs

Show
Add @AccessTimeout(0) to the EJB, this means it will throw an ConcurrentAccessException immediately when this situation occurs
Docs QE Status:
NEW
Bugzilla References:
https://bugzilla.redhat.com/show_bug.cgi?id=818481

Description

A migrated Seam2.2 Booking example on EAP6 shows a deadlock between org.jboss.seam.core.SynchronizationInterceptor and stateful component instance EJB lock during an ajax request.

Summary (reformatted to be readable), org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100 is the lock for the HotelSearchingAction

13:28:32,944 http--127.0.0.1-8080-1 Trying to acquire Seam SynchronizationInterceptor hotelSearch lock
13:28:32,947 http--127.0.0.1-8080-1 Acquired Seam SynchronizationInterceptor hotelSearch lock
13:28:32,978 http--127.0.0.1-8080-1 Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100 [State = 0, empty queue][Unlocked]
13:28:32,979 http--127.0.0.1-8080-1 Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100 [State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:46]
13:28:32,980 http--127.0.0.1-8080-1 Registered tx synchronization for tx: 0:ffff7f000001:20b3094f:4f9e7717:46 associated with HotelSearchingAction
13:28:32,985 http--127.0.0.1-8080-1 HotelSearchAction.isNextPageAvailable called
13:28:32,987 http--127.0.0.1-8080-1 Released Seam SynchronizationInterceptor hotelSearch lock

13:28:32,992 http--127.0.0.1-8080-2 Trying to acquire Seam SynchronizationInterceptor hotelSearch lock
13:28:32,993 http--127.0.0.1-8080-2 Acquired Seam SynchronizationInterceptor hotelSearch lock
13:28:32,994 http--127.0.0.1-8080-2 Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100 [State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:46]

13:28:33,034 http--127.0.0.1-8080-1 Trying to acquire Seam SynchronizationInterceptor hotelSearch lock

Here is the deadlock, resolved by the Seam SynchronizationInterceptor timeout

13:28:34,034 http--127.0.0.1-8080-1 timeout on Seam SynchronizationInterceptor hotelSearch lock

13:28:34,258 http--127.0.0.1-8080-1 Before completion callback invoked on Transaction synchronization: ... Instance of HotelSearchingAction
13:28:34,259 http--127.0.0.1-8080-1 After completion callback invoked on Transaction synchronization: ... Instance of HotelSearchingAction

13:28:34,260 http--127.0.0.1-8080-2 Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100 [State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:48]
13:28:34,261 http--127.0.0.1-8080-2 Registered tx synchronization for tx: 0:ffff7f000001:20b3094f:4f9e7717:48 associated with HotelSearchingAction
13:28:34,266 http--127.0.0.1-8080-2 HotelSearchAction.isNextPageAvailable called
13:28:34,267 http--127.0.0.1-8080-2 Released Seam SynchronizationInterceptor hotelSearch lock

13:28:34,270 http--127.0.0.1-8080-1 Released lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:48]

...

See the log excerpt for more information:

13:28:32,790 DEBUG [org.apache.tomcat.util.http.Cookies] (http--127.0.0.1-8080-1) Cookies: Parsing b[]: JSESSIONID=Rxwq4-jr-qeSrVqPZreKHxNq
13:28:32,791 DEBUG [org.jboss.seam.init.Initialization] (http--127.0.0.1-8080-1) Using Java hot deploy
13:28:32,797 DEBUG [org.jboss.seam.util.Resources] (http--127.0.0.1-8080-1) Loaded resource from servlet context: jndi:/default-host/seam-booking/WEB-INF/pages.xml
13:28:32,798 DEBUG [org.ajax4jsf.webapp.BaseFilter] (http--127.0.0.1-8080-1) Filter start request processing at 30/04/12 13:28  for uri: /seam-booking/main.seam
13:28:32,798 DEBUG [org.ajax4jsf.webapp.BaseFilter] (http--127.0.0.1-8080-1) Incoming request has Content-Type header with character encoding UTF-8
13:28:32,798 DEBUG [org.ajax4jsf.webapp.BaseFilter] (http--127.0.0.1-8080-1) Filter request output to XML
13:28:32,799 DEBUG [org.ajax4jsf.webapp.BaseXMLFilter] (http--127.0.0.1-8080-1) XML filter service start processing request
13:28:32,801 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) execute(com.sun.faces.context.FacesContextImpl@4790de90)
13:28:32,802 DEBUG [org.jboss.seam.contexts.FacesLifecycle] (http--127.0.0.1-8080-1) >>> Begin JSF request for /seam-booking/main.seam
13:28:32,808 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.core.events
13:28:32,808 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postCreate.org.jboss.seam.core.events
13:28:32,808 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.web.servletContexts
13:28:32,809 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.web.servletContexts
13:28:32,809 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postCreate.org.jboss.seam.web.servletContexts
13:28:32,809 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.transaction.transaction
13:28:32,810 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.transaction.transaction
13:28:32,810 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postCreate.org.jboss.seam.transaction.transaction
13:28:32,810 DEBUG [org.jboss.seam.jsf.SeamPhaseListener] (http--127.0.0.1-8080-1) beginning transaction prior to phase: RESTORE_VIEW 1
13:28:32,811 DEBUG [org.jboss.seam.transaction.UTTransaction] (http--127.0.0.1-8080-1) beginning JTA transaction
13:28:32,802 DEBUG [org.apache.tomcat.util.http.Parameters] (http--127.0.0.1-8080-2) Set query string encoding to null
13:28:32,812 DEBUG [org.apache.tomcat.util.http.Cookies] (http--127.0.0.1-8080-2) Cookies: Parsing b[]: JSESSIONID=Rxwq4-jr-qeSrVqPZreKHxNq
13:28:32,814 DEBUG [org.jboss.seam.init.Initialization] (http--127.0.0.1-8080-2) Using Java hot deploy
13:28:32,815 DEBUG [org.jboss.seam.util.Resources] (http--127.0.0.1-8080-2) Loaded resource from servlet context: jndi:/default-host/seam-booking/WEB-INF/pages.xml
13:28:32,817 DEBUG [org.ajax4jsf.webapp.BaseFilter] (http--127.0.0.1-8080-2) Filter start request processing at 30/04/12 13:28  for uri: /seam-booking/main.seam
13:28:32,821 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.transaction.synchronizations
13:28:32,821 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.transaction.synchronizations
13:28:32,822 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postCreate.org.jboss.seam.transaction.synchronizations
13:28:32,822 DEBUG [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Looking for stateful component instance with session id: {[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}
13:28:32,822 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 0, empty queue][Unlocked] for stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}} during invocation: org.jboss.invocation.InterceptorContext@2713fcac
13:28:32,823 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:46] for stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}} during invocation: org.jboss.invocation.InterceptorContext@2713fcac
13:28:32,825 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@1131943f for tx: 0:ffff7f000001:20b3094f:4f9e7717:46 associated with stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}}
13:28:32,826 DEBUG [org.jboss.seam.transaction.EjbSynchronizations] (http--127.0.0.1-8080-1) afterBegin
13:28:32,826 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.beforePhase
13:28:32,826 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-1) Process before phase RESTORE_VIEW 1
13:28:32,827 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) Entering RestoreViewPhase
13:28:32,827 DEBUG [org.apache.tomcat.util.http.Parameters] (http--127.0.0.1-8080-1) Set encoding to UTF-8
13:28:32,827 DEBUG [org.apache.tomcat.util.http.Parameters] (http--127.0.0.1-8080-1) Start processing with input [AJAXREQUEST=_viewRoot&searchCriteria=searchCriteria&searchCriteria%3AsearchString=a&searchCriteria%3ApageSize=10&javax.faces.ViewState=j_id2&searchCriteria%3Aonkeyup=searchCriteria%3Aonkeyup&]
13:28:32,828 FINE  [javax.enterprise.resource.webcontainer.jsf.application] (http--127.0.0.1-8080-1) servletPath /main.seam
13:28:32,828 FINE  [javax.enterprise.resource.webcontainer.jsf.application] (http--127.0.0.1-8080-1) pathInfo null
13:28:32,828 FINE  [javax.enterprise.resource.webcontainer.jsf.application] (http--127.0.0.1-8080-1) URL pattern of the FacesServlet executing the current request .seam
13:28:32,829 FINE  [javax.enterprise.resource.webcontainer.jsf.application] (http--127.0.0.1-8080-1) viewId after appending the context suffix /main.xhtml
13:28:32,829 DEBUG [org.ajax4jsf.webapp.BaseFilter] (http--127.0.0.1-8080-2) Incoming request has Content-Type header with character encoding UTF-8
13:28:32,829 DEBUG [org.ajax4jsf.webapp.BaseFilter] (http--127.0.0.1-8080-2) Filter request output to XML
13:28:32,830 DEBUG [org.ajax4jsf.webapp.BaseXMLFilter] (http--127.0.0.1-8080-2) XML filter service start processing request
13:28:32,831 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-2) execute(com.sun.faces.context.FacesContextImpl@4dfbbcea)
13:28:32,829 DEBUG [org.ajax4jsf.application.AjaxStateHolder] (http--127.0.0.1-8080-1) Request for a view states holder instance
13:28:32,831 DEBUG [org.jboss.seam.contexts.FacesLifecycle] (http--127.0.0.1-8080-2) >>> Begin JSF request for /seam-booking/main.seam
13:28:32,846 DEBUG [org.ajax4jsf.component.UIAjaxSupport] (http--127.0.0.1-8080-1) Called setParent for AjaxSupport component with parent : org.richfaces.component.html.HtmlInputText
13:28:32,846 DEBUG [org.ajax4jsf.component.UIAjaxSupport] (http--127.0.0.1-8080-1) Detect newly created component
13:28:32,846 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.core.events
13:28:32,847 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postCreate.org.jboss.seam.core.events
13:28:32,847 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.web.servletContexts
13:28:32,848 DEBUG [org.ajax4jsf.component.AjaxRegionBrige] (http--127.0.0.1-8080-1) Restore State of UIAjaxComponent with Id _viewRoot
13:28:32,848 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.web.servletContexts
13:28:32,848 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postCreate.org.jboss.seam.web.servletContexts
13:28:32,849 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.transaction.transaction
13:28:32,849 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.transaction.transaction
13:28:32,849 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postCreate.org.jboss.seam.transaction.transaction
13:28:32,850 DEBUG [org.jboss.seam.jsf.SeamPhaseListener] (http--127.0.0.1-8080-2) beginning transaction prior to phase: RESTORE_VIEW 1
13:28:32,852 DEBUG [org.jboss.seam.transaction.UTTransaction] (http--127.0.0.1-8080-2) beginning JTA transaction
13:28:32,855 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) Postback: Restored view for /main.seam
13:28:32,856 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) Exiting RestoreViewPhase
13:28:32,856 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-1) Process after phase RESTORE_VIEW 1
13:28:32,856 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.afterPhase
13:28:32,857 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.core.conversationPropagation
13:28:32,857 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.core.conversationPropagation
13:28:32,857 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postCreate.org.jboss.seam.core.conversationPropagation
13:28:32,858 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.core.manager
13:28:32,858 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.core.manager
13:28:32,858 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postCreate.org.jboss.seam.core.manager
13:28:32,858 DEBUG [org.jboss.seam.core.Manager] (http--127.0.0.1-8080-1) No stored conversation
13:28:32,859 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.transaction.synchronizations
13:28:32,859 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.transaction.synchronizations
13:28:32,860 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postCreate.org.jboss.seam.transaction.synchronizations
13:28:32,860 DEBUG [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Looking for stateful component instance with session id: {[-72, -39, -85, 91, 47, -39, 68, -62, -87, -117, 33, 5, 59, 33, -19, 92]}
13:28:32,860 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@69a73d7d[State = 0, empty queue][Unlocked] for stateful component instance:  Instance of EjbSynchronizations {{[-72, -39, -85, 91, 47, -39, 68, -62, -87, -117, 33, 5, 59, 33, -19, 92]}} during invocation: org.jboss.invocation.InterceptorContext@62b60fbb
13:28:32,861 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@69a73d7d[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:48] for stateful component instance:  Instance of EjbSynchronizations {{[-72, -39, -85, 91, 47, -39, 68, -62, -87, -117, 33, 5, 59, 33, -19, 92]}} during invocation: org.jboss.invocation.InterceptorContext@62b60fbb
13:28:32,862 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@1ec2f09e for tx: 0:ffff7f000001:20b3094f:4f9e7717:48 associated with stateful component instance:  Instance of EjbSynchronizations {{[-72, -39, -85, 91, 47, -39, 68, -62, -87, -117, 33, 5, 59, 33, -19, 92]}}
13:28:32,863 DEBUG [org.jboss.seam.transaction.EjbSynchronizations] (http--127.0.0.1-8080-2) afterBegin
13:28:32,863 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.beforePhase
13:28:32,863 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-2) Process before phase RESTORE_VIEW 1
13:28:32,864 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-2) Entering RestoreViewPhase
13:28:32,864 DEBUG [org.apache.tomcat.util.http.Parameters] (http--127.0.0.1-8080-2) Set encoding to UTF-8
13:28:32,867 DEBUG [org.apache.tomcat.util.http.Parameters] (http--127.0.0.1-8080-2) Start processing with input [AJAXREQUEST=_viewRoot&searchCriteria=searchCriteria&searchCriteria%3AsearchString=a&searchCriteria%3ApageSize=10&javax.faces.ViewState=j_id2&searchCriteria%3Aonkeyup=searchCriteria%3Aonkeyup&]
13:28:32,867 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.core.ConversationIdGenerator
13:28:32,869 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.core.ConversationIdGenerator
13:28:32,869 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.this
13:28:32,869 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.this
13:28:32,870 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.method
13:28:32,870 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.method
13:28:32,870 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.parameters
13:28:32,870 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.parameters
13:28:32,871 FINE  [javax.enterprise.resource.webcontainer.jsf.application] (http--127.0.0.1-8080-2) servletPath /main.seam
13:28:32,871 FINE  [javax.enterprise.resource.webcontainer.jsf.application] (http--127.0.0.1-8080-2) pathInfo null
13:28:32,872 FINE  [javax.enterprise.resource.webcontainer.jsf.application] (http--127.0.0.1-8080-2) URL pattern of the FacesServlet executing the current request .seam
13:28:32,873 FINE  [javax.enterprise.resource.webcontainer.jsf.application] (http--127.0.0.1-8080-2) viewId after appending the context suffix /main.xhtml
13:28:32,874 DEBUG [org.ajax4jsf.application.AjaxStateHolder] (http--127.0.0.1-8080-2) Request for a view states holder instance
13:28:32,896 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.component
13:28:32,896 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.component
13:28:32,897 DEBUG [org.jboss.seam.util.Resources] (http--127.0.0.1-8080-1) Loaded resource from context classloader: vfs:/content/jboss-seam-booking.ear/jboss-seam-booking.war/WEB-INF/lib/jboss-seam-debug.jar/META-INF/debug.xhtml
13:28:32,897 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.international.statusMessages
13:28:32,898 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.international.statusMessages
13:28:32,898 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postCreate.org.jboss.seam.international.statusMessages
13:28:32,898 FINE  [javax.enterprise.resource.webcontainer.jsf.timing] (http--127.0.0.1-8080-1)  [TIMING] - [96ms] : Execution time for phase (including any PhaseListeners) -> RESTORE_VIEW 1
13:28:32,899 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.beforePhase
13:28:32,899 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-1) Process before phase APPLY_REQUEST_VALUES 2
13:28:32,900 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) Entering ApplyRequestValuesPhase
13:28:32,900 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-1) Start decoding of component _viewRoot with class org.ajax4jsf.component.AjaxViewRoot
13:28:32,900 DEBUG [org.ajax4jsf.renderkit.AjaxContainerRenderer] (http--127.0.0.1-8080-1) Decode ajax request status for _viewRoot
13:28:32,901 DEBUG [org.ajax4jsf.component.AjaxRegionBrige] (http--127.0.0.1-8080-1) Submitted AJAX request - Queue Event to AjaxListeners
13:28:32,901 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) No decoding necessary since the component messages is not an instance or a sub class of UIInput
13:28:32,901 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) UIForm with client ID searchCriteria, submitted
13:28:32,902 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-1) Start decoding of component searchCriteria:onkeyup with class org.ajax4jsf.component.html.HtmlAjaxSupport
13:28:32,902 DEBUG [org.ajax4jsf.renderkit.AjaxCommandRendererBase] (http--127.0.0.1-8080-1) Decode submit of the Ajax component searchCriteria:onkeyup
13:28:32,903 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) Set submitted value a on component 
13:28:32,903 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) new value after decoding a
13:28:32,903 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-1) Start decoding of component searchCriteria:findHotels with class org.ajax4jsf.component.html.HtmlAjaxCommandButton
13:28:32,904 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) No decoding necessary since the component SpinnerGif is not an instance or a sub class of UIInput
13:28:32,904 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-1) Start decoding of component _viewRoot:status with class org.ajax4jsf.component.html.HtmlAjaxStatus
13:28:32,904 DEBUG [org.ajax4jsf.component.UIAjaxSupport] (http--127.0.0.1-8080-2) Called setParent for AjaxSupport component with parent : org.richfaces.component.html.HtmlInputText
13:28:32,907 DEBUG [org.ajax4jsf.component.UIAjaxSupport] (http--127.0.0.1-8080-2) Detect newly created component
13:28:32,908 DEBUG [org.ajax4jsf.component.AjaxRegionBrige] (http--127.0.0.1-8080-2) Restore State of UIAjaxComponent with Id _viewRoot
13:28:32,913 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) No decoding necessary since the component MaximumResultsLabel is not an instance or a sub class of UIInput
13:28:32,913 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-2) Postback: Restored view for /main.seam
13:28:32,914 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-2) Exiting RestoreViewPhase
13:28:32,914 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-2) Process after phase RESTORE_VIEW 1
13:28:32,913 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) Set submitted value 10 on component 
13:28:32,932 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.afterPhase
13:28:32,933 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.core.conversationPropagation
13:28:32,933 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.core.conversationPropagation
13:28:32,933 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postCreate.org.jboss.seam.core.conversationPropagation
13:28:32,934 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.core.manager
13:28:32,934 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.core.manager
13:28:32,934 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postCreate.org.jboss.seam.core.manager
13:28:32,939 DEBUG [org.jboss.seam.core.Manager] (http--127.0.0.1-8080-2) No stored conversation
13:28:32,943 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) submitted value for UISelectOne component pageSize after decoding 10
13:28:32,943 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.core.ConversationIdGenerator
13:28:32,944 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.core.ConversationIdGenerator
13:28:32,944 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.this
13:28:32,944 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.this
13:28:32,944 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.method
13:28:32,945 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.method
13:28:32,945 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.parameters
13:28:32,945 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.parameters
13:28:32,946 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.component
13:28:32,946 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.component
13:28:32,944 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-1) trying to lock: hotelSearch public abstract boolean org.jboss.seam.example.booking.HotelSearching.isNextPageAvailable()
13:28:32,946 DEBUG [org.jboss.seam.util.Resources] (http--127.0.0.1-8080-2) Loaded resource from context classloader: vfs:/content/jboss-seam-booking.ear/jboss-seam-booking.war/WEB-INF/lib/jboss-seam-debug.jar/META-INF/debug.xhtml
13:28:32,947 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-1) preProceed hotelSearch public abstract boolean org.jboss.seam.example.booking.HotelSearching.isNextPageAvailable()
13:28:32,951 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.international.statusMessages
13:28:32,951 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.international.statusMessages
13:28:32,951 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postCreate.org.jboss.seam.international.statusMessages
13:28:32,952 FINE  [javax.enterprise.resource.webcontainer.jsf.timing] (http--127.0.0.1-8080-2)  [TIMING] - [121ms] : Execution time for phase (including any PhaseListeners) -> RESTORE_VIEW 1
13:28:32,953 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.beforePhase
13:28:32,953 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-2) Process before phase APPLY_REQUEST_VALUES 2
13:28:32,953 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-2) Entering ApplyRequestValuesPhase
13:28:32,954 DEBUG [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Looking for stateful component instance with session id: {[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}
13:28:32,954 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-2) Start decoding of component _viewRoot with class org.ajax4jsf.component.AjaxViewRoot
13:28:32,970 DEBUG [org.ajax4jsf.renderkit.AjaxContainerRenderer] (http--127.0.0.1-8080-2) Decode ajax request status for _viewRoot
13:28:32,973 DEBUG [org.ajax4jsf.component.AjaxRegionBrige] (http--127.0.0.1-8080-2) Submitted AJAX request - Queue Event to AjaxListeners
13:28:32,973 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) No decoding necessary since the component messages is not an instance or a sub class of UIInput
13:28:32,974 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) UIForm with client ID searchCriteria, submitted
13:28:32,974 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-2) Start decoding of component searchCriteria:onkeyup with class org.ajax4jsf.component.html.HtmlAjaxSupport
13:28:32,975 DEBUG [org.ajax4jsf.renderkit.AjaxCommandRendererBase] (http--127.0.0.1-8080-2) Decode submit of the Ajax component searchCriteria:onkeyup
13:28:32,976 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) Set submitted value a on component 
13:28:32,976 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) new value after decoding a
13:28:32,976 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-2) Start decoding of component searchCriteria:findHotels with class org.ajax4jsf.component.html.HtmlAjaxCommandButton
13:28:32,977 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) No decoding necessary since the component SpinnerGif is not an instance or a sub class of UIInput
13:28:32,977 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-2) Start decoding of component _viewRoot:status with class org.ajax4jsf.component.html.HtmlAjaxStatus
13:28:32,977 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) No decoding necessary since the component MaximumResultsLabel is not an instance or a sub class of UIInput
13:28:32,978 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 0, empty queue][Unlocked] for stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}} during invocation: org.jboss.invocation.InterceptorContext@fe39ebf
13:28:32,979 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:46] for stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}} during invocation: org.jboss.invocation.InterceptorContext@fe39ebf
13:28:32,980 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@28cb15bf for tx: 0:ffff7f000001:20b3094f:4f9e7717:46 associated with stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}}
13:28:32,981 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.hotelSearch
13:28:32,981 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.hotelSearch
13:28:32,981 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.this
13:28:32,982 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.this
13:28:32,982 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.method
13:28:32,982 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.method
13:28:32,983 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.parameters
13:28:32,984 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.parameters
13:28:32,985 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.component
13:28:32,985 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.component
13:28:32,985 TRACE [org.jboss.seam.example.booking.HotelSearchingAction] (http--127.0.0.1-8080-1) isNextPageAvailable
13:28:32,986 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preRemoveVariable.hotels
13:28:32,986 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postRemoveVariable.hotels
13:28:32,987 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-1) unlocking hotelSearch public abstract boolean org.jboss.seam.example.booking.HotelSearching.isNextPageAvailable()
13:28:32,987 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-1) Start decoding of component searchResults with class org.ajax4jsf.component.html.HtmlAjaxOutputPanel
13:28:32,981 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) Set submitted value 10 on component 
13:28:32,991 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) submitted value for UISelectOne component pageSize after decoding 10
13:28:32,992 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-2) trying to lock: hotelSearch public abstract boolean org.jboss.seam.example.booking.HotelSearching.isNextPageAvailable()
13:28:32,993 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-2) preProceed hotelSearch public abstract boolean org.jboss.seam.example.booking.HotelSearching.isNextPageAvailable()
13:28:32,994 DEBUG [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Looking for stateful component instance with session id: {[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}
13:28:32,994 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:46] for stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}} during invocation: org.jboss.invocation.InterceptorContext@511d9ca5
13:28:32,987 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) Exiting ApplyRequestValuesPhase
13:28:33,006 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-1) Process after phase APPLY_REQUEST_VALUES 2
13:28:33,006 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.afterPhase
13:28:33,006 FINE  [javax.enterprise.resource.webcontainer.jsf.timing] (http--127.0.0.1-8080-1)  [TIMING] - [107ms] : Execution time for phase (including any PhaseListeners) -> APPLY_REQUEST_VALUES 2
13:28:33,007 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.beforePhase
13:28:33,008 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-1) Process before phase PROCESS_VALIDATIONS 3
13:28:33,008 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) Entering ProcessValidationsPhase
13:28:33,033 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-1) No conversion necessary for value a of component searchString
13:28:33,034 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-1) trying to lock: hotelSearch public abstract java.lang.String org.jboss.seam.example.booking.HotelSearching.getSearchString()
13:28:34,034 ERROR [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-1) timeout on hotelSearch public abstract java.lang.String org.jboss.seam.example.booking.HotelSearching.getSearchString()
13:28:34,133 DEBUG [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-1) 

 [redacted, see threaddump.txt and thredinfo.txt]

13:28:34,229 WARNING [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) javax.el.ELException: /main.xhtml @23,94 value="#{hotelSearch.searchString}": org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch: javax.faces.FacesException: javax.el.ELException: /main.xhtml @23,94 value="#{hotelSearch.searchString}": org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch
	at javax.faces.component.UIOutput.getValue(UIOutput.java:187) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.component.UIInput.validate(UIInput.java:880) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.component.UIInput.executeValidate(UIInput.java:1072) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.component.UIInput.processValidators(UIInput.java:672) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.component.UIForm.processValidators(UIForm.java:234) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at org.ajax4jsf.component.AjaxViewRoot$3.invokeContextCallback(AjaxViewRoot.java:439) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.component.AjaxViewRoot.processPhase(AjaxViewRoot.java:238) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.component.AjaxViewRoot.processValidators(AjaxViewRoot.java:455) [richfaces-impl.jar:3.3.1.SP3]
	at com.sun.faces.lifecycle.ProcessValidationsPhase.execute(ProcessValidationsPhase.java:76) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:100) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.webapp.FacesServlet.service(FacesServlet.java:265) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:83) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.IdentityFilter.doFilter(IdentityFilter.java:40) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.MultipartFilter.doFilter(MultipartFilter.java:90) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.ExceptionFilter.doFilter(ExceptionFilter.java:64) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.RedirectFilter.doFilter(RedirectFilter.java:45) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:178) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.webapp.BaseFilter.handleRequest(BaseFilter.java:295) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.webapp.BaseFilter.processUploadsAndHandleRequest(BaseFilter.java:373) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:500) [richfaces-impl.jar:3.3.1.SP3]
	at org.jboss.seam.web.Ajax4jsfFilter.doFilter(Ajax4jsfFilter.java:56) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.LoggingFilter.doFilter(LoggingFilter.java:60) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.HotDeployFilter.doFilter(HotDeployFilter.java:53) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter.doFilter(SeamFilter.java:158) [jboss-seam.jar:2.2.5.EAP5]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.1.1.Final-redhat-1.jar:7.1.1.Final-redhat-1]
	at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) [jboss-as-web-7.1.1.Final-redhat-1.jar:7.1.1.Final-redhat-1]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at java.lang.Thread.run(Thread.java:679) [rt.jar:1.6.0_24]
Caused by: javax.el.ELException: /main.xhtml @23,94 value="#{hotelSearch.searchString}": org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch
	at com.sun.facelets.el.TagValueExpression.getValue(TagValueExpression.java:76) [jsf-facelets.jar:1.1.15.B1-patch-01]
	at javax.faces.component.UIOutput.getValue(UIOutput.java:184) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	... 47 more
Caused by: org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch
	at org.jboss.seam.core.SynchronizationInterceptor.aroundInvoke(SynchronizationInterceptor.java:75) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.intercept.ClientSideInterceptor.invoke(ClientSideInterceptor.java:54) [jboss-seam.jar:2.2.5.EAP5]
	at org.javassist.tmp.java.lang.Object_$$_javassist_seam_4.getSearchString(Object_$$_javassist_seam_4.java)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_24]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.6.0_24]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.6.0_24]
	at java.lang.reflect.Method.invoke(Method.java:616) [rt.jar:1.6.0_24]
	at javax.el.BeanELResolver.getValue(BeanELResolver.java:302) [jboss-el-api_2.2_spec-1.0.1.Final-redhat-0-todo.jar:1.0.1.Final]
	at com.sun.faces.el.DemuxCompositeELResolver._getValue(DemuxCompositeELResolver.java:173) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at com.sun.faces.el.DemuxCompositeELResolver.getValue(DemuxCompositeELResolver.java:200) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at org.jboss.el.parser.AstPropertySuffix.getValue(AstPropertySuffix.java:53) [jboss-el.jar:1.0_02.CR6]
	at org.jboss.el.parser.AstValue.getValue(AstValue.java:67) [jboss-el.jar:1.0_02.CR6]
	at org.jboss.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:186) [jboss-el.jar:1.0_02.CR6]
	at com.sun.facelets.el.TagValueExpression.getValue(TagValueExpression.java:71) [jsf-facelets.jar:1.1.15.B1-patch-01]
	... 48 more

13:28:34,250 SEVERE [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-1) JSF1054: (Phase ID: PROCESS_VALIDATIONS 3, View ID: /main.xhtml) Exception thrown during phase execution: javax.faces.event.PhaseEvent[source=com.sun.faces.lifecycle.LifecycleImpl@37ea14c3]
13:28:34,251 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-1) Process after phase PROCESS_VALIDATIONS 3
13:28:34,252 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.afterPhase
13:28:34,252 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.faces.validation
13:28:34,252 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.faces.validation
13:28:34,252 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.postCreate.org.jboss.seam.faces.validation
13:28:34,253 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.validationFailed
13:28:34,253 DEBUG [org.jboss.seam.jsf.SeamPhaseListener] (http--127.0.0.1-8080-1) committing transaction after phase: PROCESS_VALIDATIONS 3
13:28:34,253 DEBUG [org.jboss.seam.transaction.UTTransaction] (http--127.0.0.1-8080-1) committing JTA transaction
13:28:34,254 DEBUG [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Looking for stateful component instance with session id: {[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}
13:28:34,254 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:46] for stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}} during invocation: org.jboss.invocation.InterceptorContext@9d379d2
13:28:34,255 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 2, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:46] for stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}} during invocation: org.jboss.invocation.InterceptorContext@9d379d2
13:28:34,256 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Released lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:46]
13:28:34,256 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Before completion callback invoked on Transaction synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@1131943f of stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}}
13:28:34,257 DEBUG [org.jboss.seam.transaction.EjbSynchronizations] (http--127.0.0.1-8080-1) beforeCompletion
13:28:34,257 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.beforeTransactionCompletion
13:28:34,258 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Before completion callback invoked on Transaction synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@28cb15bf of stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}}
13:28:34,259 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) After completion callback invoked on Transaction synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@28cb15bf of stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}}
13:28:34,260 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:48] for stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}} during invocation: org.jboss.invocation.InterceptorContext@511d9ca5
13:28:34,261 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@20862402 for tx: 0:ffff7f000001:20b3094f:4f9e7717:48 associated with stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}}
13:28:34,262 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.hotelSearch
13:28:34,262 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.hotelSearch
13:28:34,263 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.this
13:28:34,263 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.this
13:28:34,263 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.method
13:28:34,264 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.method
13:28:34,264 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.parameters
13:28:34,264 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.parameters
13:28:34,264 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.component
13:28:34,265 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.component
13:28:34,266 TRACE [org.jboss.seam.example.booking.HotelSearchingAction] (http--127.0.0.1-8080-2) isNextPageAvailable
13:28:34,266 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preRemoveVariable.hotels
13:28:34,266 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postRemoveVariable.hotels
13:28:34,267 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-2) unlocking hotelSearch public abstract boolean org.jboss.seam.example.booking.HotelSearching.isNextPageAvailable()
13:28:34,267 DEBUG [org.ajax4jsf.renderkit.RendererBase] (http--127.0.0.1-8080-2) Start decoding of component searchResults with class org.ajax4jsf.component.html.HtmlAjaxOutputPanel
13:28:34,268 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-2) Exiting ApplyRequestValuesPhase
13:28:34,268 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-2) Process after phase APPLY_REQUEST_VALUES 2
13:28:34,268 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.afterPhase
13:28:34,269 FINE  [javax.enterprise.resource.webcontainer.jsf.timing] (http--127.0.0.1-8080-2)  [TIMING] - [1317ms] : Execution time for phase (including any PhaseListeners) -> APPLY_REQUEST_VALUES 2
13:28:34,269 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.beforePhase
13:28:34,269 DEBUG [org.ajax4jsf.event.AjaxPhaseListener] (http--127.0.0.1-8080-2) Process before phase PROCESS_VALIDATIONS 3
13:28:34,270 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Released lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:48]
13:28:34,270 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) After completion callback invoked on Transaction synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@1131943f of stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}}
13:28:34,271 DEBUG [org.jboss.seam.transaction.EjbSynchronizations] (http--127.0.0.1-8080-1) afterCompletion
13:28:34,271 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.afterTransactionCompletion
13:28:34,271 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Released lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 0, empty queue][Unlocked]
13:28:34,272 DEBUG [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Looking for stateful component instance with session id: {[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}
13:28:34,272 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 0, empty queue][Unlocked] for stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}} during invocation: org.jboss.invocation.InterceptorContext@1806c96b
13:28:34,273 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:4c] for stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}} during invocation: org.jboss.invocation.InterceptorContext@1806c96b
13:28:34,270 FINE  [javax.enterprise.resource.webcontainer.jsf.lifecycle] (http--127.0.0.1-8080-2) Entering ProcessValidationsPhase
13:28:34,274 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Registered tx synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@3aa0eb51 for tx: 0:ffff7f000001:20b3094f:4f9e7717:4c associated with stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}}
13:28:34,275 FINE  [javax.enterprise.resource.webcontainer.jsf.renderkit] (http--127.0.0.1-8080-2) No conversion necessary for value a of component searchString
13:28:34,275 DEBUG [org.jboss.seam.transaction.EjbSynchronizations] (http--127.0.0.1-8080-1) afterBegin
13:28:34,276 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-2) trying to lock: hotelSearch public abstract java.lang.String org.jboss.seam.example.booking.HotelSearching.getSearchString()
13:28:34,276 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-2) preProceed hotelSearch public abstract java.lang.String org.jboss.seam.example.booking.HotelSearching.getSearchString()
13:28:34,276 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Before completion callback invoked on Transaction synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@3aa0eb51 of stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}}
13:28:34,277 DEBUG [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Looking for stateful component instance with session id: {[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}
13:28:34,278 DEBUG [org.jboss.seam.transaction.EjbSynchronizations] (http--127.0.0.1-8080-1) beforeCompletion
13:28:34,278 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.beforeTransactionCompletion
13:28:34,279 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) After completion callback invoked on Transaction synchronization: org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization@3aa0eb51 of stateful component instance:  Instance of EjbSynchronizations {{[-76, -103, 79, 64, -6, 62, 64, -2, -117, -58, -37, -100, 49, -8, -59, 117]}}
13:28:34,279 DEBUG [org.jboss.seam.transaction.EjbSynchronizations] (http--127.0.0.1-8080-1) afterCompletion
13:28:34,279 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-1) Processing event:org.jboss.seam.afterTransactionCompletion
13:28:34,280 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-1) Released lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@40f5472d[State = 0, empty queue][Unlocked]
13:28:34,280 FINE  [javax.enterprise.resource.webcontainer.jsf.timing] (http--127.0.0.1-8080-1)  [TIMING] - [1273ms] : Execution time for phase (including any PhaseListeners) -> PROCESS_VALIDATIONS 3
13:28:34,278 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:48] for stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}} during invocation: org.jboss.invocation.InterceptorContext@743a1eb3
13:28:34,282 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 2, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:48] for stateful component instance:  Instance of HotelSearchingAction {{[-9, 127, -122, -4, 6, 79, 68, 31, -121, 93, 74, 107, -43, -92, -67, -56]}} during invocation: org.jboss.invocation.InterceptorContext@743a1eb3
13:28:34,283 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.hotelSearch
13:28:34,283 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.hotelSearch
13:28:34,283 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.this
13:28:34,283 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.this
13:28:34,284 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.method
13:28:34,284 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.method
13:28:34,284 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.parameters
13:28:34,284 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.parameters
13:28:34,285 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preSetVariable.org.jboss.seam.component
13:28:34,285 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postSetVariable.org.jboss.seam.component
13:28:34,285 TRACE [org.jboss.seam.example.booking.HotelSearchingAction] (http--127.0.0.1-8080-2) setSearchString
13:28:34,286 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.preRemoveVariable.hotels
13:28:34,286 TRACE [org.jboss.seam.core.Events] (http--127.0.0.1-8080-2) Processing event:org.jboss.seam.postRemoveVariable.hotels
13:28:34,286 TRACE [org.jboss.as.ejb3] (http--127.0.0.1-8080-2) Released lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@3effb100[State = 1, empty queue][Locked by 0:ffff7f000001:20b3094f:4f9e7717:48]
13:28:34,287 TRACE [org.jboss.seam.core.SynchronizationInterceptor] (http--127.0.0.1-8080-2) unlocking hotelSearch public abstract java.lang.String org.jboss.seam.example.booking.HotelSearching.getSearchString()
13:28:34,281 DEBUG [org.jboss.seam.web.ExceptionFilter] (http--127.0.0.1-8080-1) handling uncaught exception: javax.servlet.ServletException: javax.el.ELException: /main.xhtml @23,94 value="#{hotelSearch.searchString}": org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch
	at javax.faces.webapp.FacesServlet.service(FacesServlet.java:277) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:83) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.IdentityFilter.doFilter(IdentityFilter.java:40) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.MultipartFilter.doFilter(MultipartFilter.java:90) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.ExceptionFilter.doFilter(ExceptionFilter.java:64) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.RedirectFilter.doFilter(RedirectFilter.java:45) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:178) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.webapp.BaseFilter.handleRequest(BaseFilter.java:295) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.webapp.BaseFilter.processUploadsAndHandleRequest(BaseFilter.java:373) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:500) [richfaces-impl.jar:3.3.1.SP3]
	at org.jboss.seam.web.Ajax4jsfFilter.doFilter(Ajax4jsfFilter.java:56) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.LoggingFilter.doFilter(LoggingFilter.java:60) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.web.HotDeployFilter.doFilter(HotDeployFilter.java:53) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.servlet.SeamFilter.doFilter(SeamFilter.java:158) [jboss-seam.jar:2.2.5.EAP5]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.1.1.Final-redhat-1.jar:7.1.1.Final-redhat-1]
	at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) [jboss-as-web-7.1.1.Final-redhat-1.jar:7.1.1.Final-redhat-1]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931) [jbossweb-7.0.15.Final-redhat-0-todo.jar:]
	at java.lang.Thread.run(Thread.java:679) [rt.jar:1.6.0_24]
Caused by: javax.faces.FacesException: javax.el.ELException: /main.xhtml @23,94 value="#{hotelSearch.searchString}": org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch
	at javax.faces.component.UIOutput.getValue(UIOutput.java:187) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.component.UIInput.validate(UIInput.java:880) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.component.UIInput.executeValidate(UIInput.java:1072) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.component.UIInput.processValidators(UIInput.java:672) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.component.UIForm.processValidators(UIForm.java:234) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at org.ajax4jsf.component.AjaxViewRoot$3.invokeContextCallback(AjaxViewRoot.java:439) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.component.AjaxViewRoot.processPhase(AjaxViewRoot.java:238) [richfaces-impl.jar:3.3.1.SP3]
	at org.ajax4jsf.component.AjaxViewRoot.processValidators(AjaxViewRoot.java:455) [richfaces-impl.jar:3.3.1.SP3]
	at com.sun.faces.lifecycle.ProcessValidationsPhase.execute(ProcessValidationsPhase.java:76) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:100) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at javax.faces.webapp.FacesServlet.service(FacesServlet.java:265) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	... 36 more
Caused by: javax.el.ELException: /main.xhtml @23,94 value="#{hotelSearch.searchString}": org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch
	at com.sun.facelets.el.TagValueExpression.getValue(TagValueExpression.java:76) [jsf-facelets.jar:1.1.15.B1-patch-01]
	at javax.faces.component.UIOutput.getValue(UIOutput.java:184) [jsf-api-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	... 47 more
Caused by: org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch
	at org.jboss.seam.core.SynchronizationInterceptor.aroundInvoke(SynchronizationInterceptor.java:75) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) [jboss-seam.jar:2.2.5.EAP5]
	at org.jboss.seam.intercept.ClientSideInterceptor.invoke(ClientSideInterceptor.java:54) [jboss-seam.jar:2.2.5.EAP5]
	at org.javassist.tmp.java.lang.Object_$$_javassist_seam_4.getSearchString(Object_$$_javassist_seam_4.java)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_24]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.6.0_24]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.6.0_24]
	at java.lang.reflect.Method.invoke(Method.java:616) [rt.jar:1.6.0_24]
	at javax.el.BeanELResolver.getValue(BeanELResolver.java:302) [jboss-el-api_2.2_spec-1.0.1.Final-redhat-0-todo.jar:1.0.1.Final]
	at com.sun.faces.el.DemuxCompositeELResolver._getValue(DemuxCompositeELResolver.java:173) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at com.sun.faces.el.DemuxCompositeELResolver.getValue(DemuxCompositeELResolver.java:200) [jsf-impl-1.2_15-b01-redhat-1.jar:1.2_15-b01-FCS]
	at org.jboss.el.parser.AstPropertySuffix.getValue(AstPropertySuffix.java:53) [jboss-el.jar:1.0_02.CR6]
	at org.jboss.el.parser.AstValue.getValue(AstValue.java:67) [jboss-el.jar:1.0_02.CR6]
	at org.jboss.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:186) [jboss-el.jar:1.0_02.CR6]
	at com.sun.facelets.el.TagValueExpression.getValue(TagValueExpression.java:71) [jsf-facelets.jar:1.1.15.B1-patch-01]
	... 48 more

(the following logging info has been added to SynchronizationInterceptor:

   @AroundInvoke
   public Object aroundInvoke(InvocationContext invocation) throws Exception
   {
      log.trace("trying to lock: " + getComponent().getName() + " " + invocation.getMethod().toString());
      if ( lock.tryLock( getComponent().getTimeout(), TimeUnit.MILLISECONDS ) )
      {
         try
         {
            log.trace("preProceed "  + getComponent().getName() + " " + invocation.getMethod().toString()); 
            return invocation.proceed();
         }
         finally
         {
            log.trace("unlocking " + getComponent().getName() + " " + invocation.getMethod().toString());
            lock.unlock();
         }
      }
      else
      {
         log.error("timeout on " + getComponent().getName() + " " + invocation.getMethod().toString());
        
         // prints getAllStackTraces and dumpAllThreads info here
         // ...

         throw new LockTimeoutException("could not acquire lock on @Synchronized component: " + 
               getComponent().getName());
      }
   }

Code for the HotelSearchingAction for the sake of completeness
(note that removing the EntityManager and the queryHotels method doesn't change anything regarding this issue, the same problem occurs)

@Stateful
@Name("hotelSearch")
@Scope(ScopeType.SESSION)
@Restrict("#{identity.loggedIn}")
public class HotelSearchingAction implements HotelSearching
{
    @PersistenceContext
    private EntityManager em;
    
    private String searchString;
    private int pageSize = 10;
    private int page;
    private boolean nextPageAvailable;
   
    @DataModel
    private List<Hotel> hotels;

    private static LogProvider log = Logging.getLogProvider(HotelSearchingAction.class);
   
    public void find() 
    {
        log.trace("find");
        page = 0;
        queryHotels();
    }

    public void nextPage() 
    {
        log.trace("nextPage");
        page++;
        queryHotels();
    }
    
    private void queryHotels() {
        log.trace("queryHotels pre query");
        List<Hotel> results = em.createQuery("select h from Hotel h where lower(h.name) like #{pattern} or lower(h.city) like #{pattern} or lower(h.zip) like #{pattern} or lower(h.address) like #{pattern}")
                                .setMaxResults(pageSize+1)
                                .setFirstResult(page * pageSize)
                                .getResultList();

        // List<Hotel> results = new ArrayList<Hotel>();

        log.trace("queryHotels after query");

        nextPageAvailable = results.size() > pageSize;
        if (nextPageAvailable) 
        {
            hotels = new ArrayList<Hotel>(results.subList(0,pageSize));
        } else {
            hotels = results;
        }
    }

    public boolean isNextPageAvailable()
    {
        log.trace("isNextPageAvailable");
        return nextPageAvailable;
    }
   
   public int getPageSize() {
      log.trace("getPageSize");
      return pageSize;
   }
   
   public void setPageSize(int pageSize) {
      log.trace("setPageSize");
      this.pageSize = pageSize;
   }
   
   @Factory(value="pattern", scope=ScopeType.EVENT)
   public String getSearchPattern()
   {
      log.trace("getSearchPattern");
      return searchString==null ? 
            "%" : '%' + searchString.toLowerCase().replace('*', '%') + '%';
   }
   
   public String getSearchString()
   {
      log.trace("setSearchString");
      return searchString;
   }
   
   public void setSearchString(String searchString)
   {
      log.trace("setSearchString");
      this.searchString = searchString;
   }

   @javax.annotation.PostConstruct
   public void create() {
        log.trace("PostConstruct!");
   }
   
   @Remove
   public void destroy() {}
}

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

seam-2.2-booking-eap6.tar
310 kB
2012/05/03 6:41 AM
server.log.bz2
392 kB
2012/05/03 6:41 AM
server.log.trim
65 kB
2012/05/03 6:41 AM
threaddump.txt
29 kB
2012/05/03 6:41 AM
threadinfo.txt
20 kB
2012/05/03 6:41 AM

Activity

People

Assignee:: Marek Novotny

Reporter:: Marek Schmidt

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 2012/05/03 6:41 AM

Updated:: 2022/09/09 6:12 AM

Resolved:: 2012/07/18 4:15 AM