SQLiteCursor locking issue on close

[madhu314]

In my application which uses a cursorloader I am running into ANR and this is what the trace file looks like. What I am trying to understand here is that why would a main thread which is trying to close the cursor get blocked on itself. This issue happens randomly and I have not yet figured out a reproducible scenario. I am doubting if this is locking issue associated with sqlcipher's cursor implementation.

"main" prio=5 tid=1 WAIT
| group="main" sCount=1 dsCount=0 obj=0x415979a0 self=0x4000b010
| sysTid=9804 nice=0 sched=0/0 cgrp=apps handle=1075102172
| state=S schedstat=( 0 0 0 ) utm=3670 stm=710 core=1
at java.lang.Object.wait(Native Method)

• waiting on <0x41597da0> (a java.lang.VMThread) held by tid=1 (main)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:810)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:843)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1173)
  at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:198)
  at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:259)
  at net.sqlcipher.database.SQLiteDatabase.lock(SQLiteDatabase.java:460)
  at net.sqlcipher.database.SQLiteProgram.close(SQLiteProgram.java:294)
  at net.sqlcipher.database.SQLiteQuery.close(SQLiteQuery.java:136)
  at net.sqlcipher.database.SQLiteCursor.close(SQLiteCursor.java:510)
  at android.database.CursorWrapper.close(CursorWrapper.java:49)
  at android.database.CursorWrapper.close(CursorWrapper.java:49)
  at android.content.ContentResolver$CursorWrapperInner.close(ContentResolver.java:1860)
  at android.database.MergeCursor.close(MergeCursor.java:175)
  at android.database.CursorWrapper.close(CursorWrapper.java:49)
  at android.content.CursorLoader.deliverResult(CursorLoader.java:117)
  at android.content.CursorLoader.deliverResult(CursorLoader.java:43)

[developernotes]

Hi madhu314,

Have you overridden onLoaderReset to delete references to the current Cursor? We would need a sample to reproduce the error.

[madhu314]

I have not overridden OnLoaderReset. However I have also noticed in my ANR logs that calls to query, update or in fact any operation on db originating from content provider is causing the same issue. I am working on reproducible sample

"Thread-53135" prio=5 tid=42 WAIT
| group="main" sCount=1 dsCount=0 obj=0x42b5d548 self=0x60177580
| sysTid=5336 nice=0 sched=0/0 cgrp=apps handle=1611888552
| schedstat=( 2018333 22684417 4 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)

• waiting on <0x42573e38> (a java.lang.VMThread) held by tid=42 (Thread-53135)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:813)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:846)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1176)
  at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200)
  at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
  at net.sqlcipher.database.SQLiteDatabase.lock(SQLiteDatabase.java:460)
  at net.sqlcipher.database.SQLiteDatabase.addSQLiteClosable(SQLiteDatabase.java:382)
  at net.sqlcipher.database.SQLiteProgram.(SQLiteProgram.java:65)
  at net.sqlcipher.database.SQLiteQuery.(SQLiteQuery.java:49)
  at net.sqlcipher.database.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:42)
  at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1451)
  at net.sqlcipher.database.SQLiteDatabase.queryWithFactory(SQLiteDatabase.java:1331)
  at net.sqlcipher.database.SQLiteDatabase.query(SQLiteDatabase.java:1285)
  at net.sqlcipher.database.SQLiteDatabase.query(SQLiteDatabase.java:1405)

Do you know of any hints/clues as to why this can happen ?

[developernotes]

Hi madhu314,

This doc suggests overriding onLoaderReset to invalidate references to a Cursor to avoid memory leaks. This may not be the issue, I have not see this before. Please let us know if you are able to reproduce it in a sample.

[madhu314]

I am not at able to come up with a sample, however, I enabled database logging for lock times and traces. I noticed that lock times are huge compared to thread run time. I am using 256 bit key encryption on sqlcipher. So this explains those weird ANR logs I posted in the first note, the process gets killed when a thread is waiting on itself to the degree of 12 seconds

do you think using 256 bit key encryption is causing such huge locking times ?

05-01 17:21:19.181: D/Database(2628): lock held on /data/data/com.example.android.control/databases/calendar.db for 4005ms. Thread time was 28ms
05-01 17:21:19.181: D/Database(2628): java.lang.Exception
05-01 17:21:19.181: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.checkLockHoldTime(SQLiteDatabase.java:536)
05-01 17:21:19.181: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.unlockForced(SQLiteDatabase.java:512)
05-01 17:21:19.181: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.endTransaction(SQLiteDatabase.java:681)
05-01 17:21:19.181: D/Database(2628): at com.example.providers.calendar.CalendarProvider2.removeStaleAccounts(CalendarProvider2.java:4967)
05-01 17:21:19.181: D/Database(2628): at com.example.providers.calendar.CalendarProvider2.verifyAccounts(CalendarProvider2.java:593)
05-01 17:21:19.181: D/Database(2628): at com.example.providers.calendar.CalendarProvider2.access$3(CalendarProvider2.java:591)
05-01 17:21:19.181: D/Database(2628): at com.example.providers.calendar.CalendarProvider2$PostInitializeThread.run(CalendarProvider2.java:578)
05-01 17:21:22.023: D/Database(2628): lock held on /data/data/com.example.android.control/databases/ControlAgent.db for 1466ms. Thread time was 524ms
05-01 17:21:22.023: D/Database(2628): java.lang.Exception
05-01 17:21:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.checkLockHoldTime(SQLiteDatabase.java:536)
05-01 17:21:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.unlock(SQLiteDatabase.java:498)
05-01 17:21:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.setLocale(SQLiteDatabase.java:2105)
05-01 17:21:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.(SQLiteDatabase.java:1969)
05-01 17:21:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.openDatabase(SQLiteDatabase.java:902)
05-01 17:21:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:945)
05-01 17:21:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:146)
05-01 17:21:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:68)

05-01 17:22:22.023: D/Database(2628): lock held on /data/data/com.example.android.control/databases/EmailProvider.db for 12337ms. Thread time was 537ms
05-01 17:22:22.023: D/Database(2628): java.lang.Exception
05-01 17:22:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.checkLockHoldTime(SQLiteDatabase.java:536)
05-01 17:22:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.unlock(SQLiteDatabase.java:498)
05-01 17:22:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.setLocale(SQLiteDatabase.java:2105)
05-01 17:22:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.(SQLiteDatabase.java:1969)
05-01 17:22:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.openDatabase(SQLiteDatabase.java:902)
05-01 17:22:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:945)
05-01 17:22:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:146)
05-01 17:22:22.023: D/Database(2628): at net.sqlcipher.database.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:68)
05-01 17:22:22.023: D/Database(2628): at com.example.email.provider.EmailProvider.getDatabase(EmailProvider.java:481)
05-01 17:22:22.023: D/Database(2628): at com.example.email.provider.EmailProvider.query(EmailProvider.java:1116)
05-01 17:22:22.023: D/Database(2628): at android.content.ContentProvider.query(ContentProvider.java:652)
05-01 17:22:22.023: D/Database(2628): at android.content.ContentProvider$Transport.query(ContentProvider.java:189)
05-01 17:22:22.023: D/Database(2628): at android.content.ContentResolver.query(ContentResolver.java:372)
05-01 17:22:22.023: D/Database(2628): at android.content.ContentResolver.query(ContentResolver.java:315)

[developernotes]

Hi madhu314,

No, I don't believe it is due to a 256 bit key. This is the first report we've had of this and there are many applications using SQLCipher for Android. Are you using multiple threads within your application? Do they each access the database? If you are able to assemble a simple case that consistently reproduces the issue we would be glad to look at it further.

I have the exact same issue but it's not easy to reproduce it :(
@madhu314 did you figure out what the problem was?

[loommo]

I have the exact same issue. 3.5.9. It's all on armeabi-v7a, and I don't know if there's any connection. What can I do for it?

[developernotes]

Hi @loommo

Are you able to create a reproducible test case within the SQLCipher for Android test suite for further review?