[NXP-25618] Fix "Session is not live" error - Nuxeo Issue Tracker

XML

Word

Printable

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Won't Fix
Affects Version/s: 7.10
Fix Version/s: None
Component/s: Runtime

Description

I was able to reproduce this error on LTS 2015 with HF43. It is probably one of scenarios which can lead to this exception

First there is a transaction timeout in thread #9 during the commit of the transaction

2018-08-21 14:41:41,723 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] RESTORE_VIEW 1: 17 ms
2018-08-21 14:41:42,678 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] RENDER_RESPONSE 6: 938 ms
2018-08-21 14:57:09,584 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] RESTORE_VIEW 1: 18 ms
2018-08-21 14:57:10,474 ERROR [Nuxeo-Administrative-Statuses-Notify-Scheduler] [org.nuxeo.runtime.transaction.TransactionHelper] Unable to commit/rollback
javax.transaction.RollbackException: Unable to commit: Transaction timeout
        at org.apache.geronimo.transaction.manager.TransactionImpl.commit(TransactionImpl.java:267)
        at org.apache.geronimo.transaction.manager.TransactionManagerImpl.commit(TransactionManagerImpl.java:252)
        at org.nuxeo.runtime.jtajca.NuxeoContainer$UserTransactionImpl.commit(NuxeoContainer.java:525)
        at org.nuxeo.runtime.transaction.TransactionHelper.commitOrRollbackTransaction(TransactionHelper.java:311)
        at org.nuxeo.ecm.core.management.statuses.AdministrativeStatusManagerImpl$NotifyStatusesHandler.run(AdministrativeStatusManagerImpl.java:124)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2018-08-21 14:57:11,059 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] RENDER_RESPONSE 6: 587 ms
2018-08-21 14:57:11,060 WARN  [http-apr-0.0.0.0-8080-exec-9] [Transaction] Unexpected exception from beforeCompletion; transaction will roll back
java.lang.IllegalStateException: unknown connection org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@14001de5 in org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@532e311e
        at org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl.removeConnection(ManagedConnectionImpl.java:247)
        at org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl.close(ManagedConnectionImpl.java:257)
        at org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl.close(ConnectionImpl.java:106)
        at org.nuxeo.ecm.core.storage.sql.coremodel.SQLSession.close(SQLSession.java:125)
        at org.nuxeo.ecm.core.api.local.LocalSession.closeInThisThread(LocalSession.java:164)
        at org.nuxeo.ecm.core.api.local.LocalSession.beforeCompletion(LocalSession.java:144)
        at org.apache.geronimo.transaction.manager.TransactionImpl.beforeCompletion(TransactionImpl.java:520)
        at org.apache.geronimo.transaction.manager.TransactionImpl.beforeCompletion(TransactionImpl.java:504)
        at org.apache.geronimo.transaction.manager.TransactionImpl.beforePrepare(TransactionImpl.java:407)
        at org.apache.geronimo.transaction.manager.TransactionImpl.commit(TransactionImpl.java:255)
        at org.apache.geronimo.transaction.manager.TransactionManagerImpl.commit(TransactionManagerImpl.java:252)
        at org.nuxeo.runtime.jtajca.NuxeoContainer$UserTransactionImpl.commit(NuxeoContainer.java:525)
        at org.jboss.seam.transaction.UTTransaction.commit(UTTransaction.java:52)
        at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:617)
        at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:608)
        at org.jboss.seam.jsf.SeamPhaseListener.handleTransactionsAfterPhase(SeamPhaseListener.java:344)
        at org.jboss.seam.jsf.SeamPhaseListener.afterServletPhase(SeamPhaseListener.java:244)
        at org.jboss.seam.jsf.SeamPhaseListener.afterPhase(SeamPhaseListener.java:195)
        at com.sun.faces.lifecycle.Phase.handleAfterPhase(Phase.java:189)
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:107)
        at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:219)
...
2018-08-21 14:57:11,062 WARN  [http-apr-0.0.0.0-8080-exec-9] [org.jboss.seam.jsf.SeamPhaseListener] uncaught exception, passing to exception handler
java.lang.IllegalStateException: Could not commit transaction
        at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:629)
        at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:608)
        at org.jboss.seam.jsf.SeamPhaseListener.handleTransactionsAfterPhase(SeamPhaseListener.java:344)
        at org.jboss.seam.jsf.SeamPhaseListener.afterServletPhase(SeamPhaseListener.java:244)
        at org.jboss.seam.jsf.SeamPhaseListener.afterPhase(SeamPhaseListener.java:195)
        at com.sun.faces.lifecycle.Phase.handleAfterPhase(Phase.java:189)
...
Caused by: javax.transaction.RollbackException: Unable to commit: transaction marked for rollback
        at org.apache.geronimo.transaction.manager.TransactionImpl.commit(TransactionImpl.java:269)
        at org.apache.geronimo.transaction.manager.TransactionManagerImpl.commit(TransactionManagerImpl.java:252)
        at org.nuxeo.runtime.jtajca.NuxeoContainer$UserTransactionImpl.commit(NuxeoContainer.java:525)
        at org.jboss.seam.transaction.UTTransaction.commit(UTTransaction.java:52)
        at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:617)
        ... 89 more
2018-08-21 14:57:11,085 ERROR [http-apr-0.0.0.0-8080-exec-9] [org.jboss.seam.jsf.SeamPhaseListener] swallowing exception
java.lang.IllegalStateException: Could not commit transaction
        at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:629)
        at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:608)
        at org.jboss.seam.jsf.SeamPhaseListener.handleTransactionsAfterPhase(SeamPhaseListener.java:344)
...
Caused by: javax.transaction.RollbackException: Unable to commit: transaction marked for rollback
        at org.apache.geronimo.transaction.manager.TransactionImpl.commit(TransactionImpl.java:269)
        at org.apache.geronimo.transaction.manager.TransactionManagerImpl.commit(TransactionManagerImpl.java:252)
        at org.nuxeo.runtime.jtajca.NuxeoContainer$UserTransactionImpl.commit(NuxeoContainer.java:525)
        at org.jboss.seam.transaction.UTTransaction.commit(UTTransaction.java:52)
        at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:617)
        ... 89 more
2018-08-21 14:57:11,326 ERROR [http-apr-0.0.0.0-8080-exec-9] [org.jboss.seam.contexts.Contexts] could not discover transaction status
2018-08-21 14:57:11,413 ERROR [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.web.common.exceptionhandling.DefaultNuxeoExceptionHandler] java.lang.NullPointerException
        at org.apache.catalina.connector.Request.notifyAttributeRemoved(Request.java:1596)
        at org.apache.catalina.connector.Request.removeAttribute(Request.java:1483)
        at org.apache.catalina.connector.RequestFacade.removeAttribute(RequestFacade.java:553)
        at javax.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:248)
        at javax.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:248)
        at com.sun.faces.context.RequestMap.remove(RequestMap.java:113)
        at org.jboss.seam.contexts.BasicContext.remove(BasicContext.java:73)
        at org.jboss.seam.Component.newInstance(Component.java:2211)
        at org.jboss.seam.Component.getInstance(Component.java:2035)
        at org.jboss.seam.Component.getInstance(Component.java:2014)
        at org.jboss.seam.Component.getInstance(Component.java:2008)
        at org.jboss.seam.Component.getInstance(Component.java:1981)
        at org.jboss.seam.Component.getInstance(Component.java:1976)
        at org.jboss.seam.core.Events.instance(Events.java:157)
        at org.jboss.seam.core.Events.exists(Events.java:152)
        at org.jboss.seam.contexts.Contexts.destroy(Contexts.java:275)
        at org.jboss.seam.contexts.Contexts.flushAndDestroyContexts(Contexts.java:395)
        at org.jboss.seam.contexts.Lifecycle.endRequest(Lifecycle.java:164)
....
2018-08-21 14:57:11,414 ERROR [http-apr-0.0.0.0-8080-exec-9] [nuxeo-error-log] java.lang.NullPointerException
        at org.apache.catalina.connector.Request.notifyAttributeRemoved(Request.java:1596)
        at org.apache.catalina.connector.Request.removeAttribute(Request.java:1483)
        at org.apache.catalina.connector.RequestFacade.removeAttribute(RequestFacade.java:553)
        at javax.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:248)
        at javax.servlet.ServletRequestWrapper.removeAttribute(ServletRequestWrapper.java:248)
        at com.sun.faces.context.RequestMap.remove(RequestMap.java:113)
        at org.jboss.seam.contexts.BasicContext.remove(BasicContext.java:73)
        at org.jboss.seam.Component.newInstance(Component.java:2211)
        at org.jboss.seam.Component.getInstance(Component.java:2035)
        at org.jboss.seam.Component.getInstance(Component.java:2014)
        at org.jboss.seam.Component.getInstance(Component.java:2008)
        at org.jboss.seam.Component.getInstance(Component.java:1981)
        at org.jboss.seam.Component.getInstance(Component.java:1976)
        at org.jboss.seam.core.Events.instance(Events.java:157)
        at org.jboss.seam.core.Events.exists(Events.java:152)
        at org.jboss.seam.contexts.Contexts.destroy(Contexts.java:275)
        at org.jboss.seam.contexts.Contexts.flushAndDestroyContexts(Contexts.java:395)
        at org.jboss.seam.contexts.Lifecycle.endRequest(Lifecycle.java:164)

Then for 5 minutes the thread #9 is not used and the NuxeoConnectionTrackingCoordinator will kill the connection handle which was leaked

2018-08-21 15:02:40,837 ERROR [PoolIdleReleaseTimer] [org.nuxeo.runtime.jtajca.NuxeoConnectionTrackingCoordinator] Killed handle: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@14001de5ManagedConnectionInfo: org.apache.geronimo.connector.outbound.ManagedConnectionInfo@606eaf29. mc: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@532e311e],  was obtained by http-apr-0.0.0.0-8080-exec-9 at Tue Aug 21 14:57:10 CEST 2018 and timed out at Tue Aug 21 15:02:10 CEST 2018
java.lang.Exception: Stack Trace
        at org.apache.geronimo.connector.outbound.ConnectionInfo.setTrace(ConnectionInfo.java:119)
        at org.apache.geronimo.connector.outbound.ConnectionHandleInterceptor.getConnection(ConnectionHandleInterceptor.java:57)
        at org.apache.geronimo.connector.outbound.TCCLInterceptor.getConnection(TCCLInterceptor.java:39)
        at org.apache.geronimo.connector.outbound.ConnectionTrackingInterceptor.getConnection(ConnectionTrackingInterceptor.java:66)
        at org.apache.geronimo.connector.outbound.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:77)
        at org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionManagerWrapper.allocateConnection(NuxeoContainer.java:739)
        at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getConnection(ConnectionFactoryImpl.java:96)
        at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getSession(ConnectionFactoryImpl.java:159)
        at org.nuxeo.ecm.core.repository.RepositoryService.getSession(RepositoryService.java:230)
        at org.nuxeo.ecm.core.api.local.LocalSession.createSession(LocalSession.java:117)
        at org.nuxeo.ecm.core.api.local.LocalSession.getSession(LocalSession.java:107)
        at org.nuxeo.ecm.core.api.AbstractSession.resolveReference(AbstractSession.java:337)
        at org.nuxeo.ecm.core.api.AbstractSession.getDocument(AbstractSession.java:955)
        at org.nuxeo.ecm.webapp.context.NavigationContextBean.navigateToRef(NavigationContextBean.java:628)
        at org.nuxeo.ecm.webapp.context.NavigationContextBean.navigateTo(NavigationContextBean.java:710)

Later one of my requests reuses thread #9 and the exception "Session is not live" is thrown because it tries to reuse the SessionImpl object whose liveness has been set to false when the the connection handle was killed

2018-08-21 15:21:22,143 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] RESTORE_VIEW 1: 356 ms
2018-08-21 15:21:22,147 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] APPLY_REQUEST_VALUES 2: 3 ms
2018-08-21 15:21:22,150 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] PROCESS_VALIDATIONS 3: 3 ms
2018-08-21 15:21:22,153 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] UPDATE_MODEL_VALUES 4: 3 ms
2018-08-21 15:21:22,246 DEBUG [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener] INVOKE_APPLICATION 5: 93 ms
2018-08-21 15:21:22,255 ERROR [http-apr-0.0.0.0-8080-exec-9] [org.nuxeo.ecm.platform.web.common.exceptionhandling.DefaultNuxeoExceptionHandler] javax.servlet.ServletException: On requestURL: http://nereid2:8080/nuxeo/search/search.faces
        at org.nuxeo.ecm.platform.ui.web.rest.FancyURLFilter.doFilter(FancyURLFilter.java:138)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter.doFilter(NuxeoRequestControllerFilter.java:144)
...
Caused by: javax.servlet.ServletException: java.lang.IllegalStateException: Session is not live
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:659)
...
Caused by: javax.faces.el.EvaluationException: java.lang.IllegalStateException: Session is not live
        at javax.faces.component.MethodBindingMethodExpressionAdapter.invoke(MethodBindingMethodExpressionAdapter.java:101)
        at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:102)
...
Caused by: java.lang.IllegalStateException: Session is not live
        at org.nuxeo.ecm.core.storage.sql.SessionImpl.checkLive(SessionImpl.java:155)
        at org.nuxeo.ecm.core.storage.sql.SessionImpl.getRootNode(SessionImpl.java:304)
        at org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl.getRootNode(ConnectionImpl.java:178)
        at org.nuxeo.ecm.core.storage.sql.coremodel.SQLSession.<init>(SQLSession.java:101)
        at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getSession(ConnectionFactoryImpl.java:159)
        at org.nuxeo.ecm.core.repository.RepositoryService.getSession(RepositoryService.java:230)
        at org.nuxeo.ecm.core.api.local.LocalSession.createSession(LocalSession.java:117)
        at org.nuxeo.ecm.core.api.local.LocalSession.getSession(LocalSession.java:107)
        at org.nuxeo.ecm.core.api.AbstractSession.resolveReference(AbstractSession.java:337)
        at org.nuxeo.ecm.core.api.AbstractSession.exists(AbstractSession.java:854)
        at org.nuxeo.ecm.platform.userworkspace.core.service.AbstractUserWorkspaceImpl.getExistingUserWorkspaceRoot(AbstractUserWorkspaceImpl.java:223)
        at org.nuxeo.ecm.platform.userworkspace.core.service.AbstractUserWorkspaceImpl.getCurrentUserPersonalWorkspace(AbstractUserWorkspaceImpl.java:214)
        at org.nuxeo.ecm.platform.userworkspace.core.service.AbstractUserWorkspaceImpl.getCurrentUserPersonalWorkspace(AbstractUserWorkspaceImpl.java:199)
        at org.nuxeo.search.ui.SearchUIServiceImpl.saveSearch(SearchUIServiceImpl.java:115)
        at org.nuxeo.search.ui.seam.SearchUIActions.saveSearch(SearchUIActions.java:389)

A solution Is required by on all the SUPNXP tickets tagged sessionisnotlive
https://jira.nuxeo.com/issues/?jql=cf%5B10080%5D%20%3D%20sessionisnotlive

Attachments

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

Attachments

server.tgz
7.59 MB
2018-08-21 15:53

Issue Links

is related to

NXP-26623 Deactivate connection killer by default

Resolved

Activity

People

Assignee:

Unassigned

Reporter:

Thierry Martins

Participants:

Thierry Martins

Votes:

1 Vote for this issue

Watchers:

4 Start watching this issue

Dates

Created:

2018-08-21 15:52

Updated:

2020-12-14 14:23

Resolved:

2020-12-14 14:23

Time Tracking

Estimated:

Not Specified

Remaining:

Logged:

1h 30m