Random sqlite3 library routine called out of sequence error in MultiThreadReadWriteTest

[brody4hire]

I encountered this error one time when testing the changes in #175:

E/AndroidRuntime( 6187): FATAL EXCEPTION: Thread-41325
E/AndroidRuntime( 6187): Process: net.zetetic, PID: 6187
E/AndroidRuntime( 6187): net.sqlcipher.database.SQLiteMisuseException: library routine called out of sequence: , while compiling: select count(*) from t1;
E/AndroidRuntime( 6187):    at net.sqlcipher.database.SQLiteCompiledSql.native_compile(Native Method)
E/AndroidRuntime( 6187):    at net.sqlcipher.database.SQLiteCompiledSql.compile(SQLiteCompiledSql.java:91)
E/AndroidRuntime( 6187):    at net.sqlcipher.database.SQLiteCompiledSql.<init>(SQLiteCompiledSql.java:64)
E/AndroidRuntime( 6187):    at net.sqlcipher.database.SQLiteProgram.<init>(SQLiteProgram.java:103)
E/AndroidRuntime( 6187):    at net.sqlcipher.database.SQLiteQuery.<init>(SQLiteQuery.java:49)
E/AndroidRuntime( 6187):    at net.sqlcipher.database.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:42)
E/AndroidRuntime( 6187):    at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1447)
E/AndroidRuntime( 6187):    at net.sqlcipher.database.SQLiteDatabase.rawQuery(SQLiteDatabase.java:1416)
E/AndroidRuntime( 6187):    at net.zetetic.tests.MultiThreadReadWriteTest$Reader.getCurrentTableCount(MultiThreadReadWriteTest.java:118)
E/AndroidRuntime( 6187):    at net.zetetic.tests.MultiThreadReadWriteTest$Reader.run(MultiThreadReadWriteTest.java:94)
E/AndroidRuntime( 6187):    at java.lang.Thread.run(Thread.java:818)
W/ActivityManager(  946):   Force finishing activity net.zetetic/.TestSuiteActivity

Second test round with the changes in #175 passed OK. I am very suspicious that this is an intermittent problem lurking in the library, and/or perhaps in the test.

This is caused by attempting to call sqlite3_prepare16_v2() [in net_sqlcipher_database_SQLiteCompiledSql.cpp] with a sqite3 handle that is closed or invalid. For reference: http://stackoverflow.com/questions/8372871/library-routine-called-out-of-sequence-sqlite3-prepare-v2create-table

The solution is to check that the database connection is open and valid before attempting to prepare (compile) the statement in native code. By "database connection", I am not sure yet whether this means that we should simply verify that the Java SQLiteDatabase is in the open state or that we should also check the internal db handle. I hope it will be enough to simply check the state of the SQLiteDatabase object.

[brody4hire]

As promised in #175, I put the full log of the MultiThreadReadWriteTest run that crashed at: https://gist.github.com/brodybits/fe073d84fc82b302fd59

NOTE (update): I just noticed that the DatabaseObjectNotClosedException stack traces below show they are triggered by other test functions:

In addition, I noticed that sometimes we get net.sqlcipher.database.DatabaseObjectNotClosedException (which seems to be ignored or recovered from). I put a section where we see several of these errors at: https://gist.github.com/brodybits/48777288836976b75dae

This error was not always in the same place. For example:

• in net.sqlcipher.database.SQLiteCompiledSql.<init>:

I/MultiThreadReadWriteTest( 6187): reader thread 17 - record:222, a:one for the money b:two for the show
W/SQLiteCompiledSql( 6187): Releasing statement in a finalizer. Please ensure that you explicitly call close() on your cursor: select * from t1;
W/SQLiteCompiledSql( 6187): net.sqlcipher.database.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
W/SQLiteCompiledSql( 6187):     at net.sqlcipher.database.SQLiteCompiledSql.<init>(SQLiteCompiledSql.java:62)
W/SQLiteCompiledSql( 6187):     at net.sqlcipher.database.SQLiteProgram.<init>(SQLiteProgram.java:83)
W/SQLiteCompiledSql( 6187):     at net.sqlcipher.database.SQLiteQuery.<init>(SQLiteQuery.java:49)
W/SQLiteCompiledSql( 6187):     at net.sqlcipher.database.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:42)
W/SQLiteCompiledSql( 6187):     at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1447)
W/SQLiteCompiledSql( 6187):     at net.sqlcipher.database.SQLiteDatabase.rawQuery(SQLiteDatabase.java:1416)
W/SQLiteCompiledSql( 6187):     at net.zetetic.tests.ExportToUnencryptedDatabase.execute(ExportToUnencryptedDatabase.java:37)
W/SQLiteCompiledSql( 6187):     at net.zetetic.tests.SQLCipherTest.run(SQLCipherTest.java:30)
W/SQLiteCompiledSql( 6187):     at net.zetetic.tests.TestSuiteRunner.runSuite(TestSuiteRunner.java:38)
W/SQLiteCompiledSql( 6187):     at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:18)
W/SQLiteCompiledSql( 6187):     at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:11)
W/SQLiteCompiledSql( 6187):     at android.os.AsyncTask$2.call(AsyncTask.java:288)
W/SQLiteCompiledSql( 6187):     at java.util.concurrent.FutureTask.run(FutureTask.java:237)
W/SQLiteCompiledSql( 6187):     at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
W/SQLiteCompiledSql( 6187):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
W/SQLiteCompiledSql( 6187):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
W/SQLiteCompiledSql( 6187):     at java.lang.Thread.run(Thread.java:818)

• in net.sqlcipher.database.SQLiteDatabase.<init>:

E/Database( 6187): close() was never explicitly called on database '/data/data/net.zetetic/databases/plaintext.db' 
E/Database( 6187): net.sqlcipher.database.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/Database( 6187):  at net.sqlcipher.database.SQLiteDatabase.<init>(SQLiteDatabase.java:1943)
E/Database( 6187):  at net.sqlcipher.database.SQLiteDatabase.openDatabase(SQLiteDatabase.java:881)
E/Database( 6187):  at net.sqlcipher.database.SQLiteDatabase.openDatabase(SQLiteDatabase.java:874)
E/Database( 6187):  at net.sqlcipher.database.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:909)
E/Database( 6187):  at net.sqlcipher.database.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:905)
E/Database( 6187):  at net.zetetic.tests.ExportToUnencryptedDatabase.execute(ExportToUnencryptedDatabase.java:36)
E/Database( 6187):  at net.zetetic.tests.SQLCipherTest.run(SQLCipherTest.java:30)
E/Database( 6187):  at net.zetetic.tests.TestSuiteRunner.runSuite(TestSuiteRunner.java:38)
E/Database( 6187):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:18)
E/Database( 6187):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:11)
E/Database( 6187):  at android.os.AsyncTask$2.call(AsyncTask.java:288)
E/Database( 6187):  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
E/Database( 6187):  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
E/Database( 6187):  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
E/Database( 6187):  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
E/Database( 6187):  at java.lang.Thread.run(Thread.java:818)

• in net.sqlcipher.database.SQLiteCursor.<init>:

E/Cursor  ( 6187): Finalizing a Cursor that has not been deactivated or closed. database = /data/data/net.zetetic/databases/test.db, table = null, query = select * from t1
E/Cursor  ( 6187): net.sqlcipher.database.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/Cursor  ( 6187):  at net.sqlcipher.database.SQLiteCursor.<init>(SQLiteCursor.java:217)
E/Cursor  ( 6187):  at net.sqlcipher.database.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:53)
E/Cursor  ( 6187):  at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1447)
E/Cursor  ( 6187):  at net.sqlcipher.database.SQLiteDatabase.rawQuery(SQLiteDatabase.java:1416)
E/Cursor  ( 6187):  at net.zetetic.tests.ReadableDatabaseTest.execute(ReadableDatabaseTest.java:23)
E/Cursor  ( 6187):  at net.zetetic.tests.SQLCipherTest.run(SQLCipherTest.java:30)
E/Cursor  ( 6187):  at net.zetetic.tests.TestSuiteRunner.runSuite(TestSuiteRunner.java:38)
E/Cursor  ( 6187):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:18)
E/Cursor  ( 6187):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:11)
E/Cursor  ( 6187):  at android.os.AsyncTask$2.call(AsyncTask.java:288)
E/Cursor  ( 6187):  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
E/Cursor  ( 6187):  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
E/Cursor  ( 6187):  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
E/Cursor  ( 6187):  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
E/Cursor  ( 6187):  at java.lang.Thread.run(Thread.java:818)

I will look at these cases early next week and propose some changes with additional safeguards.

[developernotes]

Hi @brodybits

It is certainly possible there could be an issue within that specific test, there is certainly a lot going on there. That said, I haven't been able to reproduce it. What device or emulator were you running that produced this error?

[brody4hire]

It is certainly possible there could be an issue within that specific
test, there is certainly a lot going on there.

At least it seems to be a valuable test!

That said, I haven't been able to reproduce it.

I am not surprised:

What device or emulator were you running that produced this error?

It was on my Motorola Moto G which is my own dual-sim mobile, and I only
saw it one time (which is the first time I tested the changes in PR #275).
I just wanted to get #275 to pass the test suite (once) and then record the
error for later analysis.

I do kind-of remember this test failing a few times when I was working on
the corrupted database problem. (Unfortunately) I do not remember seeing
the crash before, though.

I am planning to take another look at this test tomorrow night after my
religious rest to see if I can reproduce it in a semi-predictable manner
and come up with a better explanation.

[brody4hire]

Just rebuilt the libraries with the latest changes included and ran the test suite OK (with no failures). I noticed (again) the DatabaseObjectNotClosedException stack traces that show different test functions were logged during the MultiThreadReadWriteTest:

...
I/MultiThreadReadWriteTest(32690): reader thread 7 - record:223, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(32690): reader thread 7 - record:224, a:one for the money b:two for the show
W/SQLiteCompiledSql(32690): Releasing statement in a finalizer. Please ensure that you explicitly call close() on your cursor: select * from t1;
W/SQLiteCompiledSql(32690): net.sqlcipher.database.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
W/SQLiteCompiledSql(32690):     at net.sqlcipher.database.SQLiteCompiledSql.<init>(SQLiteCompiledSql.java:62)
W/SQLiteCompiledSql(32690):     at net.sqlcipher.database.SQLiteProgram.<init>(SQLiteProgram.java:83)
W/SQLiteCompiledSql(32690):     at net.sqlcipher.database.SQLiteQuery.<init>(SQLiteQuery.java:49)
W/SQLiteCompiledSql(32690):     at net.sqlcipher.database.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:42)
W/SQLiteCompiledSql(32690):     at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1520)
W/SQLiteCompiledSql(32690):     at net.sqlcipher.database.SQLiteDatabase.rawQuery(SQLiteDatabase.java:1489)
W/SQLiteCompiledSql(32690):     at net.zetetic.tests.ExportToUnencryptedDatabase.execute(ExportToUnencryptedDatabase.java:37)
W/SQLiteCompiledSql(32690):     at net.zetetic.tests.SQLCipherTest.run(SQLCipherTest.java:30)
W/SQLiteCompiledSql(32690):     at net.zetetic.tests.TestSuiteRunner.runSuite(TestSuiteRunner.java:38)
W/SQLiteCompiledSql(32690):     at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:18)
W/SQLiteCompiledSql(32690):     at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:11)
W/SQLiteCompiledSql(32690):     at android.os.AsyncTask$2.call(AsyncTask.java:288)
W/SQLiteCompiledSql(32690):     at java.util.concurrent.FutureTask.run(FutureTask.java:237)
W/SQLiteCompiledSql(32690):     at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
W/SQLiteCompiledSql(32690):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
W/SQLiteCompiledSql(32690):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
W/SQLiteCompiledSql(32690):     at java.lang.Thread.run(Thread.java:818)
E/Database(32690): close() was never explicitly called on database '/data/data/net.zetetic/databases/plaintext.db' 
E/Database(32690): net.sqlcipher.database.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.<init>(SQLiteDatabase.java:2016)
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.openDatabase(SQLiteDatabase.java:963)
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.openDatabase(SQLiteDatabase.java:937)
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:990)
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:986)
E/Database(32690):  at net.zetetic.tests.ExportToUnencryptedDatabase.execute(ExportToUnencryptedDatabase.java:36)
E/Database(32690):  at net.zetetic.tests.SQLCipherTest.run(SQLCipherTest.java:30)
E/Database(32690):  at net.zetetic.tests.TestSuiteRunner.runSuite(TestSuiteRunner.java:38)
E/Database(32690):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:18)
E/Database(32690):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:11)
E/Database(32690):  at android.os.AsyncTask$2.call(AsyncTask.java:288)
E/Database(32690):  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
E/Database(32690):  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
E/Database(32690):  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
E/Database(32690):  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
E/Database(32690):  at java.lang.Thread.run(Thread.java:818)
I/Database(32690): sqlite returned: error code = 28, msg = file unlinked while open: /data/data/net.zetetic/databases/plaintext.db
E/Cursor  (32690): Finalizing a Cursor that has not been deactivated or closed. database = /data/data/net.zetetic/databases/test.db, table = null, query = select * from t1
E/Cursor  (32690): net.sqlcipher.database.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/Cursor  (32690):  at net.sqlcipher.database.SQLiteCursor.<init>(SQLiteCursor.java:217)
E/Cursor  (32690):  at net.sqlcipher.database.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:53)
E/Cursor  (32690):  at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1520)
E/Cursor  (32690):  at net.sqlcipher.database.SQLiteDatabase.rawQuery(SQLiteDatabase.java:1489)
E/Cursor  (32690):  at net.zetetic.tests.ReadableDatabaseTest.execute(ReadableDatabaseTest.java:23)
E/Cursor  (32690):  at net.zetetic.tests.SQLCipherTest.run(SQLCipherTest.java:30)
E/Cursor  (32690):  at net.zetetic.tests.TestSuiteRunner.runSuite(TestSuiteRunner.java:38)
E/Cursor  (32690):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:18)
E/Cursor  (32690):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:11)
E/Cursor  (32690):  at android.os.AsyncTask$2.call(AsyncTask.java:288)
E/Cursor  (32690):  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
E/Cursor  (32690):  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
E/Cursor  (32690):  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
E/Cursor  (32690):  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
E/Cursor  (32690):  at java.lang.Thread.run(Thread.java:818)
I/MultiThreadReadWriteTest(32690): reader thread 5 - record:184, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(32690): reader thread 5 - record:185, a:one for the money b:two for the show
...
I/MultiThreadReadWriteTest(32690): reader thread 1 - record:245, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(32690): reader thread 2 - record:163, a:one for the money b:two for the show
E/Database(32690): close() was never explicitly called on database '/data/data/net.zetetic/databases/test.db' 
E/Database(32690): net.sqlcipher.database.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.<init>(SQLiteDatabase.java:2016)
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.openDatabase(SQLiteDatabase.java:963)
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.openDatabase(SQLiteDatabase.java:937)
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:990)
E/Database(32690):  at net.sqlcipher.database.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:1001)
E/Database(32690):  at net.zetetic.tests.InvalidPasswordTest.execute(InvalidPasswordTest.java:21)
E/Database(32690):  at net.zetetic.tests.SQLCipherTest.run(SQLCipherTest.java:30)
E/Database(32690):  at net.zetetic.tests.TestSuiteRunner.runSuite(TestSuiteRunner.java:38)
E/Database(32690):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:18)
E/Database(32690):  at net.zetetic.tests.TestSuiteRunner.doInBackground(TestSuiteRunner.java:11)
E/Database(32690):  at android.os.AsyncTask$2.call(AsyncTask.java:288)
E/Database(32690):  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
E/Database(32690):  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
E/Database(32690):  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
E/Database(32690):  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
E/Database(32690):  at java.lang.Thread.run(Thread.java:818)
I/MultiThreadReadWriteTest(32690): reader thread 1 - record:246, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(32690): reader thread 2 - record:164, a:one for the money b:two for the show
...

I do find it especially strange that some of these test functions could show an exception thrown during an openDatabase/openOrCreateDatabase function call but still all the tests are passing OK.

[brody4hire]

When I changed TestSuiteRunner.getTestsToRun() as follows:

    private List<SQLCipherTest> getTestsToRun(){
        List<SQLCipherTest> tests = new ArrayList<SQLCipherTest>();
        tests.add(new AttachDatabaseTest());
        tests.add(new MultiThreadReadWriteTest());
        tests.add(new CipherMigrateTest());
        tests.add(new MultiThreadReadWriteTest());
        tests.add(new GetTypeFromCrossProcessCursorWrapperTest());
        tests.add(new MultiThreadReadWriteTest());
        tests.add(new InvalidPasswordTest());
        tests.add(new MultiThreadReadWriteTest());
        tests.add(new NullQueryResultTest());
/**
        [other tests commented out]
**/
        return tests;
    }
}

When I ran it, the it eventually died (second MultiThreadReadWriteTest, if I am not mistaken). When I ran it again, it failed the first, then died (I forget when).

When I uninstalled, did a clean build/install of the test suite, and ran it, it passed the first 3 then died on the second MultiThreadReadWriteTest. When I ran it again, it failed the first test, passed the next 2, then died. Same when I ran it yet again (failed the first, passed the next 2, then died).

UPDATED: This was on my Motorola Moto G. I will try this on a simulator when I get a chance. Also, I did take a look through MultiThreadReadWriteTest.java, only one minor remark that if we only join the last thread that we created we are not 100% sure that the other threads are finished by then.

[brody4hire]

When I tried the same changes to TestSuiteRunner.getTestsToRun() on an Android 4.2.2 emulator, it also died on the second instance of MultiThreadReadWriteTest.

I got the following error in logcat:

E/AndroidRuntime(  935): FATAL EXCEPTION: Thread-120
E/AndroidRuntime(  935): java.lang.IllegalStateException: database not open
E/AndroidRuntime(  935):    at net.sqlcipher.database.SQLiteDatabase.execSQL(SQLiteDatabase.java:1898)
E/AndroidRuntime(  935):    at net.zetetic.tests.MultiThreadReadWriteTest$Writer.run(MultiThreadReadWriteTest.java:63)
E/AndroidRuntime(  935):    at java.lang.Thread.run(Thread.java:856)
I/MultiThreadReadWriteTest(  935): Starting writer thread 5

But strangely enough:

• still more trace after the error in the MultiThreadReadWriteTest
• I saw some more logcat output coming even after the app crashed on the simulator.
• and I got another test result in the logcat output:

I/MultiThreadReadWriteTest(  935): reader thread 19 beginning
I/MultiThreadReadWriteTest(  935): reader thread 19 terminating
I/MultiThreadReadWriteTest(  935): reader thread 18 beginning
I/MultiThreadReadWriteTest(  935): reader thread 18 terminating
I/Zetetic (  935): Running test:Null Query Test
I/net.zetetic.sqlcipher.test(  935): Multi-threaded read/write test - success:true
I/net.zetetic.sqlcipher.test(  935): Null Query Test - success:true
I/net.zetetic.sqlcipher.test(  935): Passed: 9  Failed: 0

When I ran the test suite the second time on the emulator, it failed the first test and then died pretty fast on the first instance of the MultiThreadReadWriteTest. Some log output:

D/dalvikvm( 1283): Trying to load lib /data/app-lib/net.zetetic-1/libstlport_shared.so 0x40ce1bf0
D/dalvikvm( 1283): Added shared lib /data/app-lib/net.zetetic-1/libstlport_shared.so 0x40ce1bf0
D/dalvikvm( 1283): No JNI_OnLoad found in /data/app-lib/net.zetetic-1/libstlport_shared.so 0x40ce1bf0, skipping init
D/dalvikvm( 1283): Trying to load lib /data/app-lib/net.zetetic-1/libsqlcipher_android.so 0x40ce1bf0
D/dalvikvm( 1283): Added shared lib /data/app-lib/net.zetetic-1/libsqlcipher_android.so 0x40ce1bf0
D/dalvikvm( 1283): No JNI_OnLoad found in /data/app-lib/net.zetetic-1/libsqlcipher_android.so 0x40ce1bf0, skipping init
D/dalvikvm( 1283): Trying to load lib /data/app-lib/net.zetetic-1/libdatabase_sqlcipher.so 0x40ce1bf0
D/dalvikvm( 1283): Added shared lib /data/app-lib/net.zetetic-1/libdatabase_sqlcipher.so 0x40ce1bf0
I/Database( 1283): JNI_OnLoad called
I/Database( 1283): JNI_OnLoad register methods 
I/Zetetic ( 1283): Running test:Attach database test
I/Database( 1283): sqlite returned: error code = 1, msg = table t1 already exists
E/Database( 1283): Failure 1 (table t1 already exists) on 0x2a19af30 when preparing 'create table encrypted.t1(a,b);'.
V/Zetetic ( 1283): net.sqlcipher.database.SQLiteException: table t1 already exists: create table encrypted.t1(a,b);
I/net.zetetic.sqlcipher.test( 1283): Attach database test - success:false
I/Zetetic ( 1283): Running test:Multi-threaded read/write test
I/MultiThreadReadWriteTest( 1283): Starting writer thread 0
I/MultiThreadReadWriteTest( 1283): Starting writer thread 1
I/MultiThreadReadWriteTest( 1283): Starting writer thread 2
I/MultiThreadReadWriteTest( 1283): Starting writer thread 3
I/MultiThreadReadWriteTest( 1283): Starting writer thread 4
I/MultiThreadReadWriteTest( 1283): Starting writer thread 5
I/MultiThreadReadWriteTest( 1283): writer thread 2 beginning
I/MultiThreadReadWriteTest( 1283): writer thread 0 beginning
I/MultiThreadReadWriteTest( 1283): writer thread 4 beginning
I/MultiThreadReadWriteTest( 1283): writer thread 1 beginning
I/MultiThreadReadWriteTest( 1283): writer thread 3 beginning
I/MultiThreadReadWriteTest( 1283): Starting writer thread 6
I/MultiThreadReadWriteTest( 1283): Starting writer thread 7
I/MultiThreadReadWriteTest( 1283): writer thread 5 beginning
I/MultiThreadReadWriteTest( 1283): Starting writer thread 8
I/MultiThreadReadWriteTest( 1283): writer thread 6 beginning
I/MultiThreadReadWriteTest( 1283): Starting writer thread 9
...
I/MultiThreadReadWriteTest( 1283): Starting reader thread 18
I/MultiThreadReadWriteTest( 1283): reader thread 15 beginning
I/MultiThreadReadWriteTest( 1283): Starting reader thread 19
I/MultiThreadReadWriteTest( 1283): reader thread 17 beginning
I/MultiThreadReadWriteTest( 1283): reader thread 18 beginning
I/MultiThreadReadWriteTest( 1283): Request reader thread 0 to join
I/MultiThreadReadWriteTest( 1283): reader thread 19 beginning
I/Database( 1283): sqlite returned: error code = 1, msg = no such table: t1
W/dalvikvm( 1283): threadid=41: thread exiting with uncaught exception (group=0x40a71930)
I/Database( 1283): sqlite returned: error code = 1, msg = no such table: t1
I/Database( 1283): sqlite returned: error code = 1, msg = no such table: t1
I/Database( 1283): sqlite returned: error code = 1, msg = no such table: t1
W/dalvikvm( 1283): threadid=45: thread exiting with uncaught exception (group=0x40a71930)
W/dalvikvm( 1283): threadid=42: thread exiting with uncaught exception (group=0x40a71930)
I/Process ( 1283): Sending signal. PID: 1283 SIG: 9
I/WindowState(  285): WIN DEATH: Window{40fa0d30 u0 net.zetetic/net.zetetic.TestSuiteActivity}
I/ActivityManager(  285): Process net.zetetic (pid 1283) has died.
W/ActivityManager(  285): Force removing ActivityRecord{40ea5d70 u0 net.zetetic/.TestSuiteActivity}: app died, no saved state

I will take a closer look at the errors observed so far within the next few days, and also want to see if the same test would crash when testing with the standard (built-in) Android database library as well.

[brody4hire]

Here is how I fixed the crashing, after trial-and-error, on both the emulator and my device:

The following changes to MultiThreadReadWriteTest.java to catch exceptions that may be thrown:

--- a/src/main/java/net/zetetic/tests/MultiThreadReadWriteTest.java
+++ b/src/main/java/net/zetetic/tests/MultiThreadReadWriteTest.java
@@ -3,6 +3,7 @@ package net.zetetic.tests;
 import android.util.Log;
 import net.sqlcipher.Cursor;
 import net.sqlcipher.database.SQLiteDatabase;
+import net.sqlcipher.database.SQLiteException;
 import net.zetetic.ZeteticApplication;

 import java.io.File;
@@ -25,6 +26,7 @@ public class MultiThreadReadWriteTest extends SQLCipherTest {
         return executor.run();
     }

+    // NOTE: this function _could_ but is NOT EXPECTED to throw:
     synchronized SQLiteDatabase getDatabase(DatabaseAccessType accessType) {
         if (accessType == DatabaseAccessType.InstancePerRequest) {
             return SQLiteDatabase.openOrCreateDatabase(databaseFile, password, null);
@@ -59,14 +61,29 @@ public class MultiThreadReadWriteTest extends SQLCipherTest {
         public void run() {
             android.os.Process.setThreadPriority(android.os.Process.THREAD_PRIORITY_BACKGROUND);
             Log.i(TAG, String.format("writer thread %d beginning", id));
+
+            // NOTE: _could_ but is NOT EXPECTED to throw:
             SQLiteDatabase writer = getDatabase(accessType);
-            writer.execSQL("create table if not exists t1(a,b)");
-            for (int index = 0; index < size; index++) {
+
+            try {
+              // XXX TBD fix indent:
+              writer.execSQL("create table if not exists t1(a,b)");
+              for (int index = 0; index < size; index++) {
                 Log.i(TAG, String.format("writer thread %d - insert data for row:%d", id, index));
                 writer.execSQL("insert into t1(a,b) values(?, ?)",
                         new Object[]{"one for the money", "two for the show"});
+              }
+
+            } catch (Exception ex){
+                Log.e(TAG, "Writer test failed with exception", ex);
+            }
+
+            try {
+                closeDatabase(writer, accessType);
+            } catch (Exception ex){
+                Log.e(TAG, "Writer test failed with exception", ex);
             }
-            closeDatabase(writer, accessType);
+
             Log.i(TAG, String.format("writer thread %d terminating", id));
         }
     }
@@ -86,6 +108,22 @@ public class MultiThreadReadWriteTest extends SQLCipherTest {
             android.os.Process.setThreadPriority(android.os.Process.THREAD_PRIORITY_BACKGROUND);
             Log.i(TAG, String.format("reader thread %d beginning", id));
             SQLiteDatabase reader = getDatabase(accessType);
+
             int currentCount = 0;
+            // NOTE: _could_ but is NOT EXPECTED to throw:
             int updatedCount = getCurrentTableCount(reader);
-            while (currentCount == 0 || currentCount != updatedCount) {
+
+            try {
+              // XXX TBD fix indent:
+              while (currentCount == 0 || currentCount != updatedCount) {
                 logRecordsBetween(reader, currentCount, updatedCount);
                 currentCount = updatedCount;
                 updatedCount = getCurrentTableCount(reader);
+              }
+            } catch (Exception ex){
+                Log.e(TAG, "Reader test failed with exception", ex);
             }
+
             closeDatabase(reader, accessType);
             Log.i(TAG, String.format("reader thread %d terminating", id));
         }

then my tests are passing OK, BOTH in emulator and on my device. The first instance of the MultiThreadReadWriteTest seems to run to its normal end, the other instances of the MultiThreadReadWriteTest stop very quickly (due to the exceptions that are now caught).

I then made some quick adaptations to MultiThreadReadWriteTest to run it on the normal Android (built-in) database instead of SQLCipher (only tried this on my device so far):

--- a/src/main/java/net/zetetic/tests/MultiThreadReadWriteTest.java
+++ b/src/main/java/net/zetetic/tests/MultiThreadReadWriteTest.java
@@ -1,8 +1,12 @@
 package net.zetetic.tests;

 import android.util.Log;
-import net.sqlcipher.Cursor;
-import net.sqlcipher.database.SQLiteDatabase;
+//import net.sqlcipher.Cursor;
+//import net.sqlcipher.database.SQLiteDatabase;
+//import net.sqlcipher.database.SQLiteException;
+import android.database.Cursor;
+import android.database.sqlite.SQLiteDatabase;
+import android.database.sqlite.SQLiteException;
 import net.zetetic.ZeteticApplication;

 import java.io.File;
@@ -19,18 +23,21 @@ public class MultiThreadReadWriteTest extends SQLCipherTest {
     int threadCount = 40;

     @Override
-    public boolean execute(SQLiteDatabase database) {
+    public boolean execute(net.sqlcipher.database.SQLiteDatabase database) {
         database.close();
         executor = new ThreadExecutor(threadCount, recordsPerThread, DatabaseAccessType.Singleton);
         return executor.run();
     }

+    // NOTE: this function _could_ but is NOT EXPECTED to throw:
     synchronized SQLiteDatabase getDatabase(DatabaseAccessType accessType) {
         if (accessType == DatabaseAccessType.InstancePerRequest) {
-            return SQLiteDatabase.openOrCreateDatabase(databaseFile, password, null);
+            //return SQLiteDatabase.openOrCreateDatabase(databaseFile, password, null);
+            return SQLiteDatabase.openOrCreateDatabase(databaseFile, null);
         } else if (accessType == DatabaseAccessType.Singleton) {
             if (instance == null) {
-                instance = SQLiteDatabase.openOrCreateDatabase(databaseFile, password, null);
+                //instance = SQLiteDatabase.openOrCreateDatabase(databaseFile, password, null);
+                instance = SQLiteDatabase.openOrCreateDatabase(databaseFile, null);
             }
             return instance;
         }

Without my fixes, it would crash (in the first instance, if I am not mistaken). When I re-enabled my fixes to catch the exceptions, I had to add one more try-catch block in MultiThreadReadWriteTest.Reader.logRecordsBetween() to fix the crash (again, tried this only on my device so far):

         synchronized void logRecordsBetween(SQLiteDatabase reader, int start, int end) {
             if(!reader.isOpen()) return;
-            Cursor results = reader.rawQuery("select rowid, * from t1 where rowid between ? and ?",
+
+            Cursor results = null;
+            try {
+                results = reader.rawQuery("select rowid, * from t1 where rowid between ? and ?",
                     new String[]{String.valueOf(start), String.valueOf(end)});
+            } catch (Exception ex){
+                Log.e(TAG, "Reader test failed with exception", ex);
+            }
+
             if (results != null) {
                 Log.i(TAG, String.format("reader thread %d - writing results %d to %d", id, start, end));

So I think we can make the following conclusions:

• We need to catch all possible errors in the Reader and Writer threads to safeguard against a possible crash
• Some of the library functions should have declared what errors can be thrown (by themselves or by functions that they call) to safeguard client applications against this possible crash
• This issue originated from the built-in Android sqlite database classes in https://github.com/android/platform_frameworks_base/tree/master/core/java/android/database/sqlite and then inherited by this project

At this point, what I am thinking is to make a version of the sqlcipher-android-tests project that will run a partial version of the test suite on the normal Android database API to demonstrate this issue and then raise the issue on the Android project.

In general, I think we should try to reflect the normal Android database API as closely as possible. It is very good that this project does actually implement some of the normal Android interfaces (such as Cursor), and am thinking it would be cool to possibly implement even more.

Any feedback from the project owners would be highly appreciated.

[brody4hire]

I just tried porting a small part of the test suite to use the built-in Android database library instead of sqlcipher, with the following tests:

• AttachDatabaseTest
• MultiThreadReadWriteTest
• NullQueryResultTest
• RawQueryTest

The first time it would run OK (only ran on my device so far). If I click the button to run again, it crashed. Then when I ran it yet again (by reopening and running, if I am not mistaken), it crashed with the following in the log:

I/MultiThreadReadWriteTest(22895): reader thread 2 - record:399, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(22895): reader thread 2 - record:400, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(22895): reader thread 18 terminating
I/MultiThreadReadWriteTest(22895): reader thread 4 - record:398, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(22895): reader thread 4 - record:399, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(22895): reader thread 4 - record:400, a:one for the money b:two for the show
I/MultiThreadReadWriteTest(22895): reader thread 19 terminating
I/Zetetic (22895): Running test:Null Query Test
I/net.zetetic.android.database.test(22895): Multi-threaded read/write test - success:true
I/MultiThreadReadWriteTest(22895): reader thread 13 terminating
E/SQLiteLog(22895): (1802) os_unix.c:29901: (2) stat(/data/data/net.zetetic/databases/test.db) - 
E/SQLiteLog(22895): (1802) statement aborts at 13: [select rowid, * from t1 where rowid between ? and ?] disk I/O error
E/SQLiteQuery(22895): exception: disk I/O error (code 1802); query: select rowid, * from t1 where rowid between ? and ?
I/MultiThreadReadWriteTest(22895): reader thread 14 terminating
I/SQLiteConnectionPool(22895): The connection pool for /data/data/net.zetetic/databases/test.db has been closed but there are still 1 connections in use.  They will be closed as they are released back to the pool.
I/MultiThreadReadWriteTest(22895): reader thread 15 terminating
I/MultiThreadReadWriteTest(22895): reader thread 16 terminating
I/MultiThreadReadWriteTest(22895): reader thread 8 terminating
I/MultiThreadReadWriteTest(22895): reader thread 10 terminating
I/MultiThreadReadWriteTest(22895): reader thread 11 terminating
--------- beginning of crash
E/AndroidRuntime(22895): FATAL EXCEPTION: Thread-8300
E/AndroidRuntime(22895): Process: net.zetetic, PID: 22895
E/AndroidRuntime(22895): android.database.sqlite.SQLiteDiskIOException: disk I/O error (code 1802)
E/AndroidRuntime(22895):    at android.database.sqlite.SQLiteConnection.nativeExecuteForCursorWindow(Native Method)
E/AndroidRuntime(22895):    at android.database.sqlite.SQLiteConnection.executeForCursorWindow(SQLiteConnection.java:845)
E/AndroidRuntime(22895):    at android.database.sqlite.SQLiteSession.executeForCursorWindow(SQLiteSession.java:836)
E/AndroidRuntime(22895):    at android.database.sqlite.SQLiteQuery.fillWindow(SQLiteQuery.java:62)
E/AndroidRuntime(22895):    at android.database.sqlite.SQLiteCursor.fillWindow(SQLiteCursor.java:144)
E/AndroidRuntime(22895):    at android.database.sqlite.SQLiteCursor.getCount(SQLiteCursor.java:133)
E/AndroidRuntime(22895):    at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:197)
E/AndroidRuntime(22895):    at android.database.AbstractCursor.moveToNext(AbstractCursor.java:245)
E/AndroidRuntime(22895):    at net.zetetic.tests.MultiThreadReadWriteTest$Reader.logRecordsBetween(MultiThreadReadWriteTest.java:106)
E/AndroidRuntime(22895):    at net.zetetic.tests.MultiThreadReadWriteTest$Reader.run(MultiThreadReadWriteTest.java:92)
E/AndroidRuntime(22895):    at java.lang.Thread.run(Thread.java:818)
I/MultiThreadReadWriteTest(22895): reader thread 4 terminating
I/MultiThreadReadWriteTest(22895): reader thread 2 terminating
I/MultiThreadReadWriteTest(22895): reader thread 9 terminating
I/MultiThreadReadWriteTest(22895): reader thread 6 terminating

Also strangely enough, I do see in logcat that a couple other tests actually passed before the program crashed (trace from other programs filtered out by hand):

I/net.zetetic.android.database.test(22895): Null Query Test - success:true
I/Zetetic (22895): Running test:Raw Query Test
I/net.zetetic.android.database.test(22895): Raw Query Test - success:true
W/SQLiteConnectionPool(22895): A SQLiteConnection object for database '/data/data/net.zetetic/databases/test.db' was leaked!  Please fix your application to end transactions in progress properly and to close the database when it is no longer needed.

I hadn't seen any SQLiteDiskIOException before, that is why I am reporting this result. I haven't seen this particular error on the sqlcipher project itself (so far).

[developernotes]

@brodybits I don't think we've ever tried to compare the test suite against the standard SQLite android.database.sqlite library itself, but is certainly interesting feedback on the behavior. Obviously certain tests simply are not valid with the standard Android Java API.

We need to catch all possible errors in the Reader and Writer threads to safeguard against a possible crash
That seems totally valid.

Some of the library functions should have declared what errors can be thrown (by themselves or by functions that they call) to safeguard client applications against this possible crash

Fair enough, though that is really a misgiving of the state of the Java android.database.sqlite library at the time the project was initially snapshot. Either way, I agree it would definitely be beneficial to make that visible to the client application developer.

At this point, what I am thinking is to make a version of the sqlcipher-android-tests project that will run a partial version of the test suite on the normal Android database API to demonstrate this issue and then raise the issue on the Android project.

That is an interesting idea. We could possibly push it down into the ZeteticApplication instance so as to provide a mechanism to toggle between the standard Android android.database.sqlite implementation and that of net.sqlcipher.database on the fly? The abstract SQLCipherTest class defers much of its work to the ZeteticApplication already. We would like need to distinguish which tests should be expected to pass under their respective API's, possibly an annotation or simply separate lists of tests.

Any feedback from the project owners would be highly appreciated.

Would you like to submit a pull request for the adjustments to the MultiThreadReadWriteTest class? If not, I can assemble them from your diff above.

By the way - thank you for the thoughtful feedback on the test suite, we don't tend to receive much discussion on this!

[brody4hire]

@brodybits I don't think we've ever tried to compare the test suite against the standard SQLite android.database.sqlite library itself, but is certainly interesting feedback on the behavior. Obviously certain tests simply are not valid with the standard Android Java API.

After a long day of trial-and-error I have now discovered that in the stock Android database Java classes, SQLiteDatabase.rawQuery() can throw SQLiteException, and both SQLiteDatabase.execSQL() & SQLiteDatabase.rawQuery() can throw IllegalStateException, however this is neither declared nor documented by the upstream Android project. I have reproduced/demonstrated these cases in the following project: https://github.com/brodybits/repeat-multi-threaded-sqlcipher-android-tests-without-sqlcipher and raised a issue on the Android project here: https://code.google.com/p/android/issues/detail?id=175351

I also submitted https://code.google.com/p/android/issues/detail?id=175353 that the SQLite database functions should always throw an instance or subclass of SQLiteException, to make it easier for the developer to check that all possible exceptions are handled at compile-time.

Some of the library functions should have declared what errors can be thrown (by themselves or by functions that they call) to safeguard client applications against this possible crash

Fair enough, though that is really a misgiving of the state of the Java android.database.sqlite library at the time the project was initially snapshot. Either way, I agree it would definitely be beneficial to make that visible to the client application developer.

Right. This is really the fault of the (sqlite) database classes in the Android project and not the sqlcipher project. In general we do want to avoid diverging too far away from the stock Android database API, though just adding the throws declarations would not make the API of this project any less restrictive. I will look at this when I get a chance.

Maybe, someday, they will fix this problem in the Android project, could be in a different way.

We could possibly push it down into the ZeteticApplication instance so as to provide a mechanism to toggle between the standard Android android.database.sqlite implementation and that of net.sqlcipher.database on the fly? The abstract SQLCipherTest class defers much of its work to the ZeteticApplication already.

What I would really like to see is better abstraction, where someone has an Android database interface that exports at least the most important SQL functions regardless of which implementation s/he is actually using. Also perhaps an abstract Android database factory interface. Maybe someday I will look at this further. Unfortunately I have very limited experience dealing with annotations (came from C/C++ background).

Would you like to submit a pull request for the adjustments to the MultiThreadReadWriteTest class?

Absolutely, maybe tomorrow.

One more thing I would like to mention: taking another look at the error trace that I originally reported, it looks like an aberration (corner-case) to me since net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory() does already checks that the database is open before attempting to start the query.

I am getting ready to finish after 12 hours of work today.

[developernotes]

I have reproduced/demonstrated these cases in the following project: https://github.com/brodybits/repeat-multi-threaded-sqlcipher-android-tests-without-sqlcipher and raised a issue on the Android project here: https://code.google.com/p/android/issues/detail?id=175351

I also submitted https://code.google.com/p/android/issues/detail?id=175353 that the SQLite database functions should always throw an instance or subclass of SQLiteException, to make it easier for the developer to check that all possible exceptions are handled at compile-time.

This is great - thanks! 👍

What I would really like to see is better abstraction, where someone has an Android database interface that exports at least the most important SQL functions regardless of which implementation s/he is actually using. Also perhaps an abstract Android database factory interface. Maybe someday I will look at this further. Unfortunately I have very limited experience dealing with annotations (came from C/C++ background).

Agreed - I just put together the sqlcipher-android-tests project initially because there wasn't anything in place at the time and we need a way to verify behavior across a growing set of Android runtimes that would sometimes vary. I'm always open to rejiggering it to have better, more thorough functionality.

net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory() does already checks that the database is open before attempting to start the query.

Ah, interesting. We should make sure this check is in place elsewhere.

I am getting ready to finish after 12 hours of work today.

Sounds like a good time to break!

[brody4hire]

net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory() does already checks that the database is open before attempting to start the query.

Ah, interesting. We should make sure this check is in place elsewhere.

I already looked through the public net.sqlcipher.database.SQLiteDatabase functions and in most cases, the check does seem to be there whenever necessary. I added a test in https://github.com/brodybits/sqlcipher-android-tests/tree/closed-db-test-1 (my closed-db-test-1 branch) to test (almost) all public functions on a SQLiteDatabase object after it is closed. This is especially important to my solution for #169, as I will try to explain tomorrow.

[brody4hire]

I started preparing the changes to submit for MultiThreadReadWriteTest.java and when testing it on my mobile device (Motorola Moto G), it passed the test suite then crashed at the end with the SQLiteMisuseException exception in the log again:

E/AndroidRuntime(23587): FATAL EXCEPTION: Thread-22312
E/AndroidRuntime(23587): Process: net.zetetic, PID: 23587
E/AndroidRuntime(23587): net.sqlcipher.database.SQLiteMisuseException: library routine called out of sequence: , while compiling: select count(*) from t1;
E/AndroidRuntime(23587):    at net.sqlcipher.database.SQLiteCompiledSql.native_compile(Native Method)
E/AndroidRuntime(23587):    at net.sqlcipher.database.SQLiteCompiledSql.compile(SQLiteCompiledSql.java:91)
E/AndroidRuntime(23587):    at net.sqlcipher.database.SQLiteCompiledSql.<init>(SQLiteCompiledSql.java:64)
E/AndroidRuntime(23587):    at net.sqlcipher.database.SQLiteProgram.<init>(SQLiteProgram.java:103)
E/AndroidRuntime(23587):    at net.sqlcipher.database.SQLiteQuery.<init>(SQLiteQuery.java:49)
E/AndroidRuntime(23587):    at net.sqlcipher.database.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:42)
E/AndroidRuntime(23587):    at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1520)
E/AndroidRuntime(23587):    at net.sqlcipher.database.SQLiteDatabase.rawQuery(SQLiteDatabase.java:1489)
E/AndroidRuntime(23587):    at net.zetetic.tests.MultiThreadReadWriteTest$Reader.getCurrentTableCount(MultiThreadReadWriteTest.java:140)
E/AndroidRuntime(23587):    at net.zetetic.tests.MultiThreadReadWriteTest$Reader.run(MultiThreadReadWriteTest.java:106)
E/AndroidRuntime(23587):    at java.lang.Thread.run(Thread.java:818)
I/MultiThreadReadWriteTest(23587): reader thread 11 terminating
W/ActivityManager( 1002):   Force finishing activity net.zetetic/.TestSuiteActivity

When I ran the test suite again it passed OK.

For the record, I am keeping the changes to the test suite where I saw this error in: https://github.com/brodybits/sqlcipher-android-tests/tree/fix-multi-thread-test-part-1

I will try to make a reproducible scenario for this, cannot promise when.

Additional note: yes this error would be caught if the application catches SQLiteException but we do not expect the library to fail this way since SQLiteDatabase.rawQueryWithFactory(), which is called by SQLiteDatabase.rawQuery(), does already check that the database is open before attempting the sql query.