[NXP-14669] session leak after login failed - Nuxeo Issue Tracker

XML

Word

Printable

Details

Type: Bug
Status: Open
Priority: Minor
Resolution: Unresolved
Affects Version/s: 5.9.5-SNAPSHOT
Fix Version/s: QualifiedToSchedule
Component/s: Core VCS

Description

Login is running in auto commit mode and seems to return the connection in the pool in the wrong status. Then the connection is re-used by another thread in a transaction, and the error is detected at the time the thread is enlisting the connection in the transaction.

2014-06-27 17:39:59,665 INFO  [http-bio-0.0.0.0-8080-exec-21] [org.nuxeo.ecm.platform.ui.web.auth.NuxeoAuthenticationFilter] Login failed for foo
2014-06-27 17:40:37,639 ERROR [Nuxeo-Work-fulltextUpdater-1] [org.nuxeo.ecm.core.storage.sql.jdbc.JDBCLogger] (4) SQL: XA start error on org.apache.geronimo.transaction.manager.XidImpl@30f42c6b
javax.transaction.xa.XAException: Already started
	at org.nuxeo.ecm.core.storage.sql.jdbc.XAResourceConnectionAdapter.newXAException(XAResourceConnectionAdapter.java:152)
	at org.nuxeo.ecm.core.storage.sql.jdbc.XAResourceConnectionAdapter.start(XAResourceConnectionAdapter.java:54)
	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCMapper.start(JDBCMapper.java:1340)
	at org.nuxeo.ecm.core.storage.sql.SoftRefCachingMapper.start(SoftRefCachingMapper.java:178)
	at org.nuxeo.ecm.core.storage.sql.SessionImpl.start(SessionImpl.java:1401)
	at org.apache.geronimo.transaction.manager.WrapperNamedXAResource.start(WrapperNamedXAResource.java:111)
	at org.apache.geronimo.transaction.manager.TransactionImpl.enlistResource(TransactionImpl.java:202)
	at org.apache.geronimo.connector.outbound.TransactionEnlistingInterceptor.getConnection(TransactionEnlistingInterceptor.java:60)
	at org.apache.geronimo.connector.outbound.TransactionCachingInterceptor.getConnection(TransactionCachingInterceptor.java:101)
	at org.apache.geronimo.connector.outbound.ConnectionHandleInterceptor.getConnection(ConnectionHandleInterceptor.java:43)
	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:915)
	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getConnection(ConnectionFactoryImpl.java:105)
	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getSession(ConnectionFactoryImpl.java:176)
	at org.nuxeo.ecm.core.api.local.LocalSession.createSession(LocalSession.java:130)
	at org.nuxeo.ecm.core.api.local.LocalSession.connect(LocalSession.java:88)
	at sun.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.nuxeo.ecm.core.api.TransactionalCoreSessionWrapper.invoke(TransactionalCoreSessionWrapper.java:131)
	at com.sun.proxy.$Proxy100.connect(Unknown Source)
	at org.nuxeo.ecm.core.api.CoreInstance.acquireCoreSession(CoreInstance.java:185)
	at org.nuxeo.ecm.core.api.CoreInstance.openCoreSession(CoreInstance.java:179)
	at org.nuxeo.ecm.core.api.CoreInstance.openCoreSessionSystem(CoreInstance.java:113)
	at org.nuxeo.ecm.core.work.AbstractWork.initSession(AbstractWork.java:252)
	at org.nuxeo.ecm.core.work.AbstractWork.initSession(AbstractWork.java:241)
	at org.nuxeo.ecm.core.storage.sql.FulltextUpdaterWork.work(FulltextUpdaterWork.java:97)
	at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransaction(AbstractWork.java:355)
	at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransactionAndCheckExceptions(AbstractWork.java:316)
	at org.nuxeo.ecm.core.work.AbstractWork.run(AbstractWork.java:284)
	at org.nuxeo.ecm.core.work.WorkHolder.run(WorkHolder.java:52)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)
2014-06-27 17:40:37,642 WARN  [Nuxeo-Work-fulltextUpdater-1] [Transaction] Unable to enlist XAResource org.apache.geronimo.transaction.manager.WrapperNamedXAResource@7d14c07e, errorCode: -6
javax.transaction.xa.XAException: Already started
	at org.nuxeo.ecm.core.storage.sql.jdbc.XAResourceConnectionAdapter.newXAException(XAResourceConnectionAdapter.java:152)
	at org.nuxeo.ecm.core.storage.sql.jdbc.XAResourceConnectionAdapter.start(XAResourceConnectionAdapter.java:54)
	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCMapper.start(JDBCMapper.java:1340)
	at org.nuxeo.ecm.core.storage.sql.SoftRefCachingMapper.start(SoftRefCachingMapper.java:178)
	at org.nuxeo.ecm.core.storage.sql.SessionImpl.start(SessionImpl.java:1401)
	at org.apache.geronimo.transaction.manager.WrapperNamedXAResource.start(WrapperNamedXAResource.java:111)
	at org.apache.geronimo.transaction.manager.TransactionImpl.enlistResource(TransactionImpl.java:202)
	at org.apache.geronimo.connector.outbound.TransactionEnlistingInterceptor.getConnection(TransactionEnlistingInterceptor.java:60)
	at org.apache.geronimo.connector.outbound.TransactionCachingInterceptor.getConnection(TransactionCachingInterceptor.java:101)
	at org.apache.geronimo.connector.outbound.ConnectionHandleInterceptor.getConnection(ConnectionHandleInterceptor.java:43)
	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:915)
	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getConnection(ConnectionFactoryImpl.java:105)
	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getSession(ConnectionFactoryImpl.java:176)
	at org.nuxeo.ecm.core.api.local.LocalSession.createSession(LocalSession.java:130)
	at org.nuxeo.ecm.core.api.local.LocalSession.connect(LocalSession.java:88)
	at sun.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.nuxeo.ecm.core.api.TransactionalCoreSessionWrapper.invoke(TransactionalCoreSessionWrapper.java:131)
	at com.sun.proxy.$Proxy100.connect(Unknown Source)
	at org.nuxeo.ecm.core.api.CoreInstance.acquireCoreSession(CoreInstance.java:185)
	at org.nuxeo.ecm.core.api.CoreInstance.openCoreSession(CoreInstance.java:179)
	at org.nuxeo.ecm.core.api.CoreInstance.openCoreSessionSystem(CoreInstance.java:113)
	at org.nuxeo.ecm.core.work.AbstractWork.initSession(AbstractWork.java:252)
	at org.nuxeo.ecm.core.work.AbstractWork.initSession(AbstractWork.java:241)
	at org.nuxeo.ecm.core.storage.sql.FulltextUpdaterWork.work(FulltextUpdaterWork.java:97)
	at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransaction(AbstractWork.java:355)
	at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransactionAndCheckExceptions(AbstractWork.java:316)
	at org.nuxeo.ecm.core.work.AbstractWork.run(AbstractWork.java:284)
	at org.nuxeo.ecm.core.work.WorkHolder.run(WorkHolder.java:52)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)
2014-06-27 17:40:37,643 ERROR [Nuxeo-Work-fulltextUpdater-1] [org.nuxeo.ecm.core.work.AbstractWork] Exception during work: FulltextUpdaterWork(261ba77d-e9cf-4ea8-ab08-b9f9896f0a0e, , Progress(?%, ?/0), null)
java.lang.IllegalStateException: Concurrency Error: Session was started in thread 84 (http-bio-0.0.0.0-8080-exec-21) but is being used in thread 26 (Nuxeo-Work-fulltextUpdater-1)
	at org.nuxeo.ecm.core.storage.sql.SessionImpl.checkThread(SessionImpl.java:216)
	at org.nuxeo.ecm.core.storage.sql.SessionImpl.checkLive(SessionImpl.java:166)
	at org.nuxeo.ecm.core.storage.sql.SessionImpl.getRootNode(SessionImpl.java:316)
	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl.getRootNode(ConnectionImpl.java:188)
	at org.nuxeo.ecm.core.storage.sql.coremodel.SQLSession.<init>(SQLSession.java:152)
	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getSession(ConnectionFactoryImpl.java:176)
	at org.nuxeo.ecm.core.api.local.LocalSession.createSession(LocalSession.java:130)
	at org.nuxeo.ecm.core.api.local.LocalSession.connect(LocalSession.java:88)
	at sun.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.nuxeo.ecm.core.api.TransactionalCoreSessionWrapper.invoke(TransactionalCoreSessionWrapper.java:131)
	at com.sun.proxy.$Proxy100.connect(Unknown Source)
	at org.nuxeo.ecm.core.api.CoreInstance.acquireCoreSession(CoreInstance.java:185)
	at org.nuxeo.ecm.core.api.CoreInstance.openCoreSession(CoreInstance.java:179)
	at org.nuxeo.ecm.core.api.CoreInstance.openCoreSessionSystem(CoreInstance.java:113)
	at org.nuxeo.ecm.core.work.AbstractWork.initSession(AbstractWork.java:252)
	at org.nuxeo.ecm.core.work.AbstractWork.initSession(AbstractWork.java:241)
	at org.nuxeo.ecm.core.storage.sql.FulltextUpdaterWork.work(FulltextUpdaterWork.java:97)
	at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransaction(AbstractWork.java:355)
	at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransactionAndCheckExceptions(AbstractWork.java:316)
	at org.nuxeo.ecm.core.work.AbstractWork.run(AbstractWork.java:284)
	at org.nuxeo.ecm.core.work.WorkHolder.run(WorkHolder.java:52)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:744)
2014-06-27 17:41:27,413 ERROR [Finalizer] [org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionTrackingCoordinator] cleanup errors
org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionTrackingCoordinator$Context$AllocationErrors: leaked {handle: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@793297b4ManagedConnectionInfo: org.apache.geronimo.connector.outbound.ManagedConnectionInfo@2a4186b7. mc: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@51943cc1]=org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionTrackingCoordinator$Context$Allocation: Allocation stack trace of handle: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@793297b4ManagedConnectionInfo: org.apache.geronimo.connector.outbound.ManagedConnectionInfo@2a4186b7. mc: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@51943cc1]} connections in Nuxeo-Work-fulltextUpdater-1
	at org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionTrackingCoordinator$Context.checkIsEmpty(NuxeoContainer.java:844)
	at org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionTrackingCoordinator$Context.finalize(NuxeoContainer.java:836)
	at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
	at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:101)
	at java.lang.ref.Finalizer.access$100(Finalizer.java:32)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:190)
	Suppressed: org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionTrackingCoordinator$Context$Allocation: Allocation stack trace of handle: org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl@793297b4ManagedConnectionInfo: org.apache.geronimo.connector.outbound.ManagedConnectionInfo@2a4186b7. mc: org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl@51943cc1]
		at org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionTrackingCoordinator.handleObtained(NuxeoContainer.java:864)
		at org.apache.geronimo.connector.outbound.ConnectionTrackingInterceptor.getConnection(ConnectionTrackingInterceptor.java:67)
		at org.apache.geronimo.connector.outbound.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:77)
		at org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionManagerWrapper.allocateConnection(NuxeoContainer.java:915)
		at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getConnection(ConnectionFactoryImpl.java:105)
		at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getSession(ConnectionFactoryImpl.java:176)
		at org.nuxeo.ecm.core.api.local.LocalSession.createSession(LocalSession.java:130)
		at org.nuxeo.ecm.core.api.local.LocalSession.connect(LocalSession.java:88)
		at sun.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
		at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
		at java.lang.reflect.Method.invoke(Method.java:606)
		at org.nuxeo.ecm.core.api.TransactionalCoreSessionWrapper.invoke(TransactionalCoreSessionWrapper.java:131)
		at com.sun.proxy.$Proxy100.connect(Unknown Source)
		at org.nuxeo.ecm.core.api.CoreInstance.acquireCoreSession(CoreInstance.java:185)
		at org.nuxeo.ecm.core.api.CoreInstance.openCoreSession(CoreInstance.java:179)
		at org.nuxeo.ecm.core.api.CoreInstance.openCoreSessionSystem(CoreInstance.java:113)
		at org.nuxeo.ecm.core.work.AbstractWork.initSession(AbstractWork.java:252)
		at org.nuxeo.ecm.core.work.AbstractWork.initSession(AbstractWork.java:241)
		at org.nuxeo.ecm.core.storage.sql.FulltextUpdaterWork.work(FulltextUpdaterWork.java:97)
		at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransaction(AbstractWork.java:355)
		at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransactionAndCheckExceptions(AbstractWork.java:316)
		at org.nuxeo.ecm.core.work.AbstractWork.run(AbstractWork.java:284)
		at org.nuxeo.ecm.core.work.WorkHolder.run(WorkHolder.java:52)
		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
		at java.lang.Thread.run(Thread.java:744)

Attachments

Issue Links

depends on

NXP-14185 fix storage connection leak at startup

Resolved

Activity

People

Assignee:

Stéphane Lacoin

Reporter:

Stéphane Lacoin

Participants:

Stéphane Lacoin

Votes:

0 Vote for this issue

Watchers:

1 Start watching this issue

Dates

Created:

2014-06-30 08:57

Updated:

2015-10-07 05:20