ArrayIndexOutOfBoundsException during TransactionTest2.transactionsWithInterrupts

[Nathan Williams]

Persistit r347

Failure during automated build on Jenkins:
http://172.16.20.104:8080/view/persistit/job/public-persistit/15/

First time I've ever seen this, but it certainly looks bad. Nothing left over on the instance this ran on but an inspection and some thought experiments are probably in order. Test output copied below.

Error Message
Starting and ending balance don't agree expected:<0> but was:<-12587>

Stacktrace
java.lang.AssertionError: Starting and ending balance don't agree expected:<0> but was:<-12587>
 at org.junit.Assert.fail(Assert.java:91)
 at org.junit.Assert.failNotEquals(Assert.java:645)
 at org.junit.Assert.assertEquals(Assert.java:126)
 at org.junit.Assert.assertEquals(Assert.java:470)
 at com.persistit.TransactionTest2.transactionsWithInterrupts(TransactionTest2.java:226)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
 at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
 at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
 at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
 at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
 at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
 at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
 at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
 at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
 at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
 at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
 at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
 at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
 at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
 at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
 at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
 at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)

Standard Output

Computing balance
Starting balance is 0
Completed transactions: 738046
Failed transactions: 1
Retried transactions: 3322

CurrentCount=163 AbortedCount=8 LongRunningCount=0 FreeCount=4,950
atCache=Floor=2,167,412 Ceiling=2,167,412 Low=MAX High=MIN Count=0
Ending balance is -12587 which DISAGREES

Standard Error
<snip>
java.lang.ArrayIndexOutOfBoundsException: -32745
 at com.persistit.util.Util.getLong(Util.java:81)
 at com.persistit.MVV.visitAllVersions(MVV.java:702)
 at com.persistit.Exchange.mvccFetch(Exchange.java:2684)
 at com.persistit.Exchange.fetchFromValueInternal(Exchange.java:2800)
 at com.persistit.Exchange.fetchFromBufferInternal(Exchange.java:2761)
 at com.persistit.Exchange.searchAndFetchInternal(Exchange.java:2832)
 at com.persistit.Exchange.fetch(Exchange.java:2737)
 at com.persistit.Exchange.fetch(Exchange.java:2594)
 at com.persistit.TransactionTest2.transfer(TransactionTest2.java:292)
 at com.persistit.TransactionTest2.runIt(TransactionTest2.java:245)
 at com.persistit.TransactionTest2$2.run(TransactionTest2.java:189)
 at java.lang.Thread.run(Thread.java:619)
<snip>

The snips in stderr are dozens of "Transaction neither committed nor rolled back" messages. Full log attached.

[Peter Beaman (pbeaman)]

I also saw an instance of this recently. Elevating priority to Critical.

[Peter Beaman (pbeaman)]

As reported this appears to be two bugs.

One is an isolation protocol failure: evidently a version of a value is seen as valid within a transaction when it should not be, or vice-versa. (The "balance" in TransactionTest2 DISAGREES.)

The other is an AIOOBE that indicates the content of Value object is corrupt.

We are able to reproduce the first problem fairly regularly by lengthening the TT2 run time and changing some of its parameters. We also have a mechanism for the bug and a proposed fix. The mechanism is identical to the one for Assertion in MVV.prune() https://bugs.launchpad.net/akiban-persistit/+bug/1032846.

The mechanism is caused by a pair of conditional statements in TransactionIndex and is explained more fully in bug 1032846.