Attachment 915655 Details for Bug 900326 – Comment

Comment

comment_5417408.txt (text/plain), 72.12 KB, created by Marek Schmidt on 2012-04-30 16:00:30 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Marek Schmidt

Created: 2012-04-30 16:00:30 UTC

Size: 72.12 KB

patch

obsolete

>Steps to Reproduce: 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
>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 
>project_key: JBPAPP6
>
>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
>
>{noformat}
>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]
>
>...
>{noformat}
>
>See the log excerpt for more information:
>
>{noformat}
>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
>{noformat}
>
>
>(the following logging info has been added to SynchronizationInterceptor:
>{code}
>   @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}
>
>
>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)
>
>{code}
>@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() {}
>}
>{code}

Actions: View

Attachments on bug 900326: 681637 | 681638 | 681639 | 681640 | 681641 | 915655