[
https://forge.continuent.org/jira/browse/SEQUOIA-1007?page=comments#action_14157
]
Robert Hodges commented on SEQUOIA-1007:
----------------------------------------
I cannot prove conclusively that this is the root cause of the issue but it
looks very likely that we may be getting caught by a thread synchronization
issue. The recovery log currently uses a single connection for all writes to
the recovery log. The connection is returned by
RecoveryLog.getDatabaseConnection(), which returns the connection. A lot of
code in the RecoveryLog has invocations like the following:
PreparedStatement stmt = recoveryLog.getDatabaseConnection().prepareStatement(
"DELETE FROM " + recoveryLog.getCheckpointTableName());
stmt.executeUpdate();
This is not thread-safe because another thread may simultaneously be doing a
different operation on the recovery log. It so happens that many JDBC drivers
have synchronization to prevent more than one operation on a connection at a
time. However, others (including MySQL and Oracle) do not.
The answer appears to be to add a connection pool to the recovery log and
convert all invocations to getDatabaseConnection() to use the pool. This would
eliminate synchronization errors fully. (There are 61 calls to
RecoveryLog.getDatabaseConnection(); these would need to be updated to return
connections to the pool.)
> Recovery log stored in MySQL gets duplicate key errors following update
> failure
> -------------------------------------------------------------------------------
>
> Key: SEQUOIA-1007
> URL: https://forge.continuent.org/jira/browse/SEQUOIA-1007
> Project: Sequoia
> Type: Bug
> Components: Recovery Log
> Versions: Sequoia 2.10
> Environment: Tested on Linux with logs stored in MySQL.
> Reporter: Robert Hodges
> Priority: Critical
> Fix For: sequoia 2.10.11
>
>
> We have seen a number of cases where recovery logs stored in MySQL get
> strange errors as if the connection were being altered or closed. This shows
> up intermittently in tests of the commercial product and in Sequoia as well.
> Here's a sample:
> 2007-11-21 07:57:18,284 ERROR sequoia.controller.recoverylog Failed to log
> INSERT INTO ITEM
> (ITEMID,SELLERID,DESCRIPTION,BID_PRICE,START_TIME,END_TIME,BID_COUNT) VALUES
> ('ITEM1-679', 'UID1-436',
> 'wBiLEQDxCgQI2gHf94MVR4Y6UI5TcGzub21yjHAzAfMnRBmanVow6rR1RzE2XorMkfeH4fjzBxHmytS0dIvBkjbdYZVVu4LmYnyr'
> ,'1560041.4', '2005-10-20', '2005-10-30', '0')
> com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: No operations
> allowed after statement closed.
> at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:888)
> at com.mysql.jdbc.Statement.checkClosed(Statement.java:380)
> at
> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1297)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1541)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1455)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1440)
> at
> org.continuent.sequoia.controller.recoverylog.events.LogRequestEvent.execute(LogRequestEvent.java:102)
> at
> org.continuent.sequoia.controller.recoverylog.LoggerThread.run(LoggerThread.java:700)
> 2007-11-21 07:57:18,399 ERROR sequoia.controller.recoverylog Failed to log
> INSERT INTO ITEM
> (ITEMID,SELLERID,DESCRIPTION,BID_PRICE,START_TIME,END_TIME,BID_COUNT) VALUES
> ('ITEM1-679', 'UID1-436',
> 'wBiLEQDxCgQI2gHf94MVR4Y6UI5TcGzub21yjHAzAfMnRBmanVow6rR1RzE2XorMkfeH4fjzBxHmytS0dIvBkjbdYZVVu4LmYnyr'
> ,'1560041.4', '2005-10-20', '2005-10-30', '0')
> com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException:
> Duplicate entry '4669' for key 1
> at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:931)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2941)
> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1623)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1715)
> at com.mysql.jdbc.Connection.execSQL(Connection.java:3249)
> at
> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1268)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1541)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1455)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1440)
> at
> org.continuent.sequoia.controller.recoverylog.events.LogRequestEvent.execute(LogRequestEvent.java:102)
> at
> org.continuent.sequoia.controller.recoverylog.LoggerThread.run(LoggerThread.java:700)
> 2007-11-21 07:57:18,404 ERROR sequoia.controller.recoverylog WARNING! Your
> recovery log is probably corrupted, you should perform a restore log operation
> 2007-11-21 07:57:18,406 ERROR sequoia.controller.recoverylog Logger thread
> was unable to log LogRequestEvent: Log entry: log id4669 (A) transactionId:0
> requestId:5210 vlogin:user status: E sql:INSERT INTO ITEM
> (ITEMID,SELLERID,DESCRIPTION,BID_PRICE,START_TIME,END_TIME,BID_COUNT) VALUES
> ('ITEM1-679', 'UID1-436',
> 'wBiLEQDxCgQI2gHf94MVR4Y6UI5TcGzub21yjHAzAfMnRBmanVow6rR1RzE2XorMkfeH4fjzBxHmytS0dIvBkjbdYZVVu4LmYnyr'
> ,'1560041.4', '2005-10-20', '2005-10-30', '0') params:null because of
> com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException:
> Duplicate entry '4669' for key 1
> com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException:
> Duplicate entry '4669' for key 1
> at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:931)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2941)
> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1623)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1715)
> at com.mysql.jdbc.Connection.execSQL(Connection.java:3249)
> at
> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1268)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1541)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1455)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1440)
> at
> org.continuent.sequoia.controller.recoverylog.events.LogRequestEvent.execute(LogRequestEvent.java:102)
> at
> org.continuent.sequoia.controller.recoverylog.LoggerThread.run(LoggerThread.java:700)
>
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
https://forge.continuent.org/jira/secure/Administrators.jspa
-
For more information on JIRA, see:
http://www.atlassian.com/software/jira
_______________________________________________
Sequoia mailing list
[email protected]
https://forge.continuent.org/mailman/listinfo/sequoia
