"Thread waiting for lock during cleanup" and "Lock owned during cleanup" warnings in EAP 6
Environment
- Red Hat JBoss Enterprise Application Platform (EAP) 6
Issue
In our server log there are warnings appearing in pairs:
WARN [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (http-/10.1.2.3:8080-1) Lock owned during cleanup: java.lang.Throwable: Lock owned during cleanup
at java.net.SocketInputStream.socketRead0(Native Method) [rt.jar:1.6.0_26]
at java.net.SocketInputStream.read(SocketInputStream.java:129) [rt.jar:1.6.0_26]
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3116) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3570) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4110) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2815) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.LoadBalancedMySQLConnection.execSQL(LoadBalancedMySQLConnection.java:158) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322) [mysql-connector-java-5.1.25.jar:]
at com.mysql.jdbc.JDBC4PreparedStatement.executeQuery(JDBC4PreparedStatement.java) [mysql-connector-java-5.1.25.jar:]
at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:107)
at org.jboss.jca.adapters.jdbc.jdk6.CachedPreparedStatementJDK6.executeQuery(CachedPreparedStatementJDK6.java)
at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:462)
at org.jboss.jca.adapters.jdbc.jdk6.WrappedPreparedStatementJDK6.executeQuery(WrappedPreparedStatementJDK6.java)
at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.Loader.getResultSet(Loader.java:1953) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.Loader.doQuery(Loader.java:802) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.Loader.loadEntity(Loader.java:2037) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:86) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:76) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3293) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
...
at com.example.some.Code.method()
...
and
WARN [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (http-/10.1.2.3:8080-1) IJ000607: ResourceException cleaning up managed connection: org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@76594b28[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@7a1ea03b connection handles=0 lastUse=1377351353808 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@1e6f9a58 pool internal context=SemaphoreArrayListManagedConnectionPool@14c5d02c[pool=MyDataSource]]: javax.resource.ResourceException: Still active locks
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.cleanup(BaseWrapperManagedConnection.java:356)
at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.returnConnection(SemaphoreArrayListManagedConnectionPool.java:436)
at org.jboss.jca.core.connectionmanager.pool.AbstractPool.returnConnection(AbstractPool.java:561)
at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.returnManagedConnection(AbstractConnectionManager.java:425)
at org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener.connectionClosed(NoTxConnectionListener.java:90)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:557)
at org.jboss.jca.adapters.jdbc.WrappedConnection.close(WrappedConnection.java:264)
at org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6.close(WrappedConnectionJDK6.java)
at org.hibernate.connection.DatasourceConnectionProvider.closeConnection(DatasourceConnectionProvider.java:97) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.jdbc.ConnectionManager.closeConnection(ConnectionManager.java:474) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.jdbc.ConnectionManager.aggressiveRelease(ConnectionManager.java:429) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.jdbc.ConnectionManager.afterStatement(ConnectionManager.java:304) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.jdbc.AbstractBatcher.closePreparedStatement(AbstractBatcher.java:572) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.jdbc.AbstractBatcher.closeStatement(AbstractBatcher.java:291) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:307) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:234) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.Loader.doQuery(Loader.java:854) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.Loader.loadEntity(Loader.java:2037) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:86) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:76) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3293) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:285) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152) [hibernate-core-3.6.1.Final.jar:3.6.1.Final]
...
at com.example.other.Thing.method()
...
Resolution
Do not allow a connection to be used by multiple threads at once. Note that this can be caused by the use of the interleaving element with datasources in JBoss.
Related information can be found at What does javax.resource.ResourceException: Still active locks mean in JBoss?.
See also "Lock owned during cleanup" WARN during server/pool shutdown in EAP.
Root Cause
Those warnings indicate that a connection is being used by two different threads concurrently. The second thread is attempting to close a connection, but there are active locks on it. The first thread is the one that is holding the lock on the connection.
This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.
Comments