
|
If you were logged in you would be able to see more operations.
|
|
|
|
Environment:
|
Ubuntu linux, Hibernate 3.2.5.ga, MySQL 5.0.22
|
|
We use Compass in non-managed environment, where connection is got from LocalCompassBean and is wrapped by TransactionAwareDataSourceProxy. We encountered some critical problems in our application, resulting in neccessity of restarting the server and mysql daemon in our deployment environment. The problem is that Compass doesn't rollback transaction is some cases and the tables are locked after exception.
After some digging I think I found the bug in LuceneSearchEngine.commit():
public void commit(boolean onePhase) throws SearchEngineException {
verifyWithinTransaction();
try {
if (transaction != null) {
transaction.commit(onePhase);
eventManager.afterCommit(onePhase);
}
} finally {
transaction = null;
transactionState = COMMIT;
}
}
Where the exception was:
org.compass.gps.device.hibernate.HibernateGpsDeviceException: {hibernate}: Failed while updating [RCP/3825]; nested exception is org.compass.core.engine.SearchEngineException: Failed in second phase commit from sub-index [basemodel]; nested exception is org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into index_basemodel (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
org.compass.core.engine.SearchEngineException: Failed in second phase commit from sub-index [basemodel]; nested exception is org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into index_basemodel (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into index_basemodel (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
at com.mysql.jdbc.Util.getInstance(Util.java:381)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1046)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:957)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3376)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3308)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1837)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1961)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2543)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1737)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2022)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1940)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1925)
at org.apache.lucene.store.jdbc.support.JdbcTemplate.executeUpdate(JdbcTemplate.java:159)
at org.apache.lucene.store.jdbc.index.AbstractJdbcIndexOutput.close(AbstractJdbcIndexOutput.java:47)
at org.apache.lucene.index.SegmentInfos.write(SegmentInfos.java:91)
at org.apache.lucene.index.TransIndex$2.doBody(TransIndex.java:352)
at org.apache.lucene.store.Lock$With.run(Lock.java:99)
at org.apache.lucene.index.TransIndex.secondPhase(TransIndex.java:339)
at org.compass.core.lucene.engine.transaction.ReadCommittedTransaction$TransIndexManager.secondPhase(ReadCommittedTransaction.java:168)
at org.compass.core.lucene.engine.transaction.ReadCommittedTransaction.doCommit(ReadCommittedTransaction.java:269)
at org.compass.core.lucene.engine.transaction.AbstractTransaction.commit(AbstractTransaction.java:85)
at org.compass.core.lucene.engine.LuceneSearchEngine.commit(LuceneSearchEngine.java:244)
at org.compass.core.transaction.LocalTransaction.doCommit(LocalTransaction.java:93)
at org.compass.core.transaction.AbstractTransaction.commit(AbstractTransaction.java:38)
...
And further:
14:45:07,552 ERROR org.compass.core.CompassTemplate - Failed to rollback transaction, ignoring
org.compass.core.engine.SearchEngineException: Search engine transaction not successfully started or already committed/rolledback
at org.compass.core.lucene.engine.LuceneSearchEngine.verifyWithinTransaction(LuceneSearchEngine.java:223)
at org.compass.core.lucene.engine.LuceneSearchEngine.rollback(LuceneSearchEngine.java:254)
at org.compass.core.transaction.LocalTransaction.doRollback(LocalTransaction.java:119)
at org.compass.core.transaction.AbstractTransaction.rollback(AbstractTransaction.java:46)
...
As we can see, the exception in transaction.commit(onePhase) results with the method return, having set before the state to COMMIT, but when commit wasn't performed properly, and more - when the afterCommit() closing connection wasn't invoked. Moreover, the rollback() is performed after exception has been thrown, but it thinks (because transactionState=COMMIT) that it's not required to do the rollback. In result after such flow we have a locked table in MySQL.
We use compass 1.1.1 for now, but I indicated the newest release in this bug, because as I see these codes were not changed since.
|
|
Description
|
We use Compass in non-managed environment, where connection is got from LocalCompassBean and is wrapped by TransactionAwareDataSourceProxy. We encountered some critical problems in our application, resulting in neccessity of restarting the server and mysql daemon in our deployment environment. The problem is that Compass doesn't rollback transaction is some cases and the tables are locked after exception.
After some digging I think I found the bug in LuceneSearchEngine.commit():
public void commit(boolean onePhase) throws SearchEngineException {
verifyWithinTransaction();
try {
if (transaction != null) {
transaction.commit(onePhase);
eventManager.afterCommit(onePhase);
}
} finally {
transaction = null;
transactionState = COMMIT;
}
}
Where the exception was:
org.compass.gps.device.hibernate.HibernateGpsDeviceException: {hibernate}: Failed while updating [RCP/3825]; nested exception is org.compass.core.engine.SearchEngineException: Failed in second phase commit from sub-index [basemodel]; nested exception is org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into index_basemodel (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
org.compass.core.engine.SearchEngineException: Failed in second phase commit from sub-index [basemodel]; nested exception is org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into index_basemodel (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into index_basemodel (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
at com.mysql.jdbc.Util.getInstance(Util.java:381)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1046)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:957)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3376)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3308)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1837)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1961)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2543)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1737)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2022)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1940)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1925)
at org.apache.lucene.store.jdbc.support.JdbcTemplate.executeUpdate(JdbcTemplate.java:159)
at org.apache.lucene.store.jdbc.index.AbstractJdbcIndexOutput.close(AbstractJdbcIndexOutput.java:47)
at org.apache.lucene.index.SegmentInfos.write(SegmentInfos.java:91)
at org.apache.lucene.index.TransIndex$2.doBody(TransIndex.java:352)
at org.apache.lucene.store.Lock$With.run(Lock.java:99)
at org.apache.lucene.index.TransIndex.secondPhase(TransIndex.java:339)
at org.compass.core.lucene.engine.transaction.ReadCommittedTransaction$TransIndexManager.secondPhase(ReadCommittedTransaction.java:168)
at org.compass.core.lucene.engine.transaction.ReadCommittedTransaction.doCommit(ReadCommittedTransaction.java:269)
at org.compass.core.lucene.engine.transaction.AbstractTransaction.commit(AbstractTransaction.java:85)
at org.compass.core.lucene.engine.LuceneSearchEngine.commit(LuceneSearchEngine.java:244)
at org.compass.core.transaction.LocalTransaction.doCommit(LocalTransaction.java:93)
at org.compass.core.transaction.AbstractTransaction.commit(AbstractTransaction.java:38)
...
And further:
14:45:07,552 ERROR org.compass.core.CompassTemplate - Failed to rollback transaction, ignoring
org.compass.core.engine.SearchEngineException: Search engine transaction not successfully started or already committed/rolledback
at org.compass.core.lucene.engine.LuceneSearchEngine.verifyWithinTransaction(LuceneSearchEngine.java:223)
at org.compass.core.lucene.engine.LuceneSearchEngine.rollback(LuceneSearchEngine.java:254)
at org.compass.core.transaction.LocalTransaction.doRollback(LocalTransaction.java:119)
at org.compass.core.transaction.AbstractTransaction.rollback(AbstractTransaction.java:46)
...
As we can see, the exception in transaction.commit(onePhase) results with the method return, having set before the state to COMMIT, but when commit wasn't performed properly, and more - when the afterCommit() closing connection wasn't invoked. Moreover, the rollback() is performed after exception has been thrown, but it thinks (because transactionState=COMMIT) that it's not required to do the rollback. In result after such flow we have a locked table in MySQL.
We use compass 1.1.1 for now, but I indicated the newest release in this bug, because as I see these codes were not changed since. |
Show » |
|