Error in SqlMetadataRuleManagerTest

[leventov]

Tests run: 4, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 22.619 sec <<< FAILURE! - in io.druid.metadata.SQLMetadataRuleManagerTest
testMultipleStopAndStart(io.druid.metadata.SQLMetadataRuleManagerTest)  Time elapsed: 20.698 sec  <<< ERROR!
org.skife.jdbi.v2.exceptions.CallbackFailedException: 
org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: java.sql.SQLTransactionRollbackException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : ROW, SYSCOLUMNS, (5,12)
  Waiting XID : {237, X} , APP, DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules
  Granted XID : {217, S} 
Lock : TABLE, DRUIDTESTC0DD9B47C4DF453DAEBA2ACA4613783E_RULES, Tablelock
  Waiting XID : {217, IS} , APP, SELECT r.dataSource, r.payload FROM druidTestc0dd9b47c4df453daeba2aca4613783e_rules r INNER JOIN(SELECT dataSource, max(version) as version FROM druidTestc0dd9b47c4df453daeba2aca4613783e_rules GROUP BY dataSource) ds ON r.datasource = ds.datasource and r.version = ds.version
  Granted XID : {237, X} 
. The selected victim is XID : 237. [statement:"DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules", located:"DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules", rewritten:"DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules", arguments:{ positional:{}, named:{}, finder:[]}]
	at io.druid.metadata.SQLMetadataRuleManagerTest.dropTable(SQLMetadataRuleManagerTest.java:209)
	at io.druid.metadata.SQLMetadataRuleManagerTest.cleanup(SQLMetadataRuleManagerTest.java:204)
Caused by: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: 
java.sql.SQLTransactionRollbackException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : ROW, SYSCOLUMNS, (5,12)
  Waiting XID : {237, X} , APP, DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules
  Granted XID : {217, S} 
Lock : TABLE, DRUIDTESTC0DD9B47C4DF453DAEBA2ACA4613783E_RULES, Tablelock
  Waiting XID : {217, IS} , APP, SELECT r.dataSource, r.payload FROM druidTestc0dd9b47c4df453daeba2aca4613783e_rules r INNER JOIN(SELECT dataSource, max(version) as version FROM druidTestc0dd9b47c4df453daeba2aca4613783e_rules GROUP BY dataSource) ds ON r.datasource = ds.datasource and r.version = ds.version
  Granted XID : {237, X} 
. The selected victim is XID : 237. [statement:"DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules", located:"DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules", rewritten:"DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules", arguments:{ positional:{}, named:{}, finder:[]}]
	at io.druid.metadata.SQLMetadataRuleManagerTest.dropTable(SQLMetadataRuleManagerTest.java:209)
	at io.druid.metadata.SQLMetadataRuleManagerTest.cleanup(SQLMetadataRuleManagerTest.java:204)
Caused by: java.sql.SQLTransactionRollbackException: 
A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : ROW, SYSCOLUMNS, (5,12)
  Waiting XID : {237, X} , APP, DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules
  Granted XID : {217, S} 
Lock : TABLE, DRUIDTESTC0DD9B47C4DF453DAEBA2ACA4613783E_RULES, Tablelock
  Waiting XID : {217, IS} , APP, SELECT r.dataSource, r.payload FROM druidTestc0dd9b47c4df453daeba2aca4613783e_rules r INNER JOIN(SELECT dataSource, max(version) as version FROM druidTestc0dd9b47c4df453daeba2aca4613783e_rules GROUP BY dataSource) ds ON r.datasource = ds.datasource and r.version = ds.version
  Granted XID : {237, X} 
. The selected victim is XID : 237.
	at io.druid.metadata.SQLMetadataRuleManagerTest.dropTable(SQLMetadataRuleManagerTest.java:209)
	at io.druid.metadata.SQLMetadataRuleManagerTest.cleanup(SQLMetadataRuleManagerTest.java:204)
Caused by: org.apache.derby.iapi.error.StandardException: 
A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : ROW, SYSCOLUMNS, (5,12)
  Waiting XID : {237, X} , APP, DROP TABLE druidTestc0dd9b47c4df453daeba2aca4613783e_rules
  Granted XID : {217, S} 
Lock : TABLE, DRUIDTESTC0DD9B47C4DF453DAEBA2ACA4613783E_RULES, Tablelock
  Waiting XID : {217, IS} , APP, SELECT r.dataSource, r.payload FROM druidTestc0dd9b47c4df453daeba2aca4613783e_rules r INNER JOIN(SELECT dataSource, max(version) as version FROM druidTestc0dd9b47c4df453daeba2aca4613783e_rules GROUP BY dataSource) ds ON r.datasource = ds.datasource and r.version = ds.version
  Granted XID : {237, X} 
. The selected victim is XID : 237.
	at io.druid.metadata.SQLMetadataRuleManagerTest.dropTable(SQLMetadataRuleManagerTest.java:209)
	at io.druid.metadata.SQLMetadataRuleManagerTest.cleanup(SQLMetadataRuleManagerTest.java:204)

[jihoonson]

Where did you see this error? This test passes in my local machine.

[clintropolis]

I have encountered this error before as well, it does not happen often, though it was rather recent (~2 weeks ago) so I wonder if something has changed that has agitated this.

[leventov]

I think the problem is that SQLMetadataRuleManager.poll() is scheduled to be called asynchronously in a dedicated executor in SQLMetadataRuleManager.start(). poll() makes an inner join of the rules table with itself, that appears to be enough to cause a deadlock when the drop of this table is called in parallel (it is called in SQLMetadataRuleManagerTest.cleanup().

The problem was introduced in #5554, where the SQLMetadataRuleManagerTest.testMultipleStopAndStart() was added which calls start() and stop() repeatedly. Before, SQLMetadataRuleManager.start() was not ever called in the context of SQLMetadataRuleManagerTest.

Extra coincidental problem that leads to this condition is that stop() (that pairs start() calls in testMultipleStopAndStart()) is not actually synchronous. By the time when stop() exists, some poll() may still be executed. To ensure this is not the case, exec.awaitTermination() should be called. But this is awkward, because we don't know what timeout we should use. Alternatively, poll() could be synchronized together with start() and stop() (the started flag should be checked under the lock in poll()).

Extra:

• There is no point in future and exec being volatile.
• future.cancel is redundant before shutdownNow().
• There is a race on retryStartTime updates in poll().
• It feels to me that SQLMetadataRuleManager mixes two separate abstractions - one of scheduled polling, and another of the access to the database itself (including the implementation of poll()). But I'm uncertain about this.

[jihoonson]

Thanks @leventov. Probably SQLMetadataSegmentManager has the same bug. I'll check it.