Uploaded image for project: 'JBoss Enterprise Application Platform 6'
  1. JBoss Enterprise Application Platform 6
  2. JBPAPP6-611

Seam 2.2 booking org.jboss.seam.core.LockTimeoutException: could not acquire lock on @Synchronized component: hotelSearch

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Rejected
    • Affects Version/s: EAP 6.0.0 ER 6_Beta2
    • Fix Version/s: EAP 6.0.0 ER 7
    • Component/s: EJB
    • 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
      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 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

      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() {}
      }
      

        Gliffy Diagrams

          Attachments

          1. seam-2.2-booking-eap6.tar
            310 kB
          2. server.log.bz2
            392 kB
          3. server.log.trim
            65 kB
          4. threaddump.txt
            29 kB
          5. threadinfo.txt
            20 kB

            Issue Links

              Activity

                People

                • Assignee:
                  sgilda Sande Gilda
                  Reporter:
                  maschmid Marek Schmidt
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: