Patch: Fix SQLiteCursor locking issue.

[promeG]

Hi, I have encountered deadlock problem when applying SQLCipher to my application.

There is a closed issue about it : #97

I compared the lock method used in SQLCipher with AOSP4.0.1, and found that there are some difference.

After doing some changes, I finally get rid of deadlock problem. Here is the patch: https://github.com/promeG/SQLCipher-Android-Fix-Deadlock-Patch

I hope it can help with other people who have the same problem.

SQLCipher is a great project, thank you for your hard work!

[developernotes]

Hello promeG,

Thank you for your interest in SQLCipher for Android. We would prefer a pull request for changes like this, as it helps the integration process as well as provided proper attribution of the changes within the source tree. Also, it would be beneficial if there was test coverage for this type of change within the test suite. Thanks!

[promeG]

Hi, dheerajb

Sorry I can't find the problem based on your log, maybe you can try my modified libraries?

I have uploaded them on: https://github.com/promeG/SQLCipher-Android-Fix-Deadlock-Patch/tree/master/libs

[dheerajb]

Hey promeG

you mentioned "I compared the lock method used in SQLCipher with AOSP4.0.1, and found that there are some difference."

Can you please elaborate which file in AOSP you compared to?

[promeG]

Hi dheerajb

I went through with package "android.database.sqlite" in AOSP, and compared SQLCipher's SQLiteDatabase.java and SQLiteProgram.java. May be there are other classes which implement lock() improperly.

An online refrence to AOSP code:
http://grepcode.com/file/repository.grepcode.com/java/ext/com.google.android/android/4.0.3_r1/android/database/sqlite/SQLiteDatabase.java#SQLiteDatabase
http://grepcode.com/file/repository.grepcode.com/java/ext/com.google.android/android/4.0.3_r1/android/database/sqlite/SQLiteProgram.java#SQLiteProgram

Hope this will help you.

[dheerajb]

Still no luck.

I have one question. I understand we should avoid db operations in MAIN Thread, but a simple query should not cause an ANR. It was fine when we were not using SQLCipher.

Now the same logic throws an ANR when we switched to SQLCipher.

I am surprised why lock() is taking so much time to cause an ANR.

"main" prio=5 tid=1 WAIT

| group="main" sCount=1 dsCount=0 obj=0x41b79578 self=0x41ae6a60

| sysTid=6675 nice=0 sched=0/0 cgrp=apps handle=1074970620

| state=S schedstat=( 11494402761 2196695859 19554 ) utm=811 stm=337 core=3

at java.lang.Object.wait(Native Method)

• waiting on <0x41b79978> (a java.lang.VMThread) held by tid=1 (main)

  at java.lang.Thread.parkFor(Thread.java:1205)

  at sun.misc.Unsafe.park(Unsafe.java:325)

  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:459)

  at net.sqlcipher.database.SQLiteDatabase.addSQLiteClosable(SQLiteDatabase.java:381)

  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:1450)

  at net.sqlcipher.database.SQLiteDatabase.queryWithFactory(SQLiteDatabase.java:1330)

  at net.sqlcipher.database.SQLiteDatabase.query(SQLiteDatabase.java:1284)

  at net.sqlcipher.database.SQLiteDatabase.query(SQLiteDatabase.java:1404)

[developernotes]

Hello @dheerajb

If you are able to recreate the issue in isolation, we would be glad to look at it further. Please feel free to create a test case within the SQLCipher for Android test suite and we can delve deeper into what the cause may be. Thanks!

[draak567]

The issue seems to be the way the AOSP email client code interacts with SQLCipher.

In my experience, especially when using Exchange ActiveSync support and a large mailbox with calendar and contact list support, it's not uncommon at startup for the e-mail SQL database to be accessed by several threads simultaneously performing both read and write operations.

You can see the code that uses the SQL database here:
http://grepcode.com/file/repository.grepcode.com/java/ext/com.google.android/android-apps/4.0.1_r1/com/android/email/provider/EmailProvider.java

In that scenario, replacing the Android standard SQLiteDatabase object by SQLCipher's occasionally leads to a deadlock with at least 10-15 threads deadlocked on the database object's lock. Because of the email client's design, which accesses the database from the UI thread in the Welcome activity, the deadlock eventually leads to an ANR.

We ran into this problem when we attempted to integrate the AOSP e-mail client into our own application with the additional requirement that the database be encrypted.

The issue occurred more often the more emails/contacts/calendar entries were present in the user's Exchange inbox and the slower the target handset was.

[dheerajb]

Sorry was trying to edit my original post and deleted by mistake.
( Is their a way to retrieve it?)

Here goes the issue we are facing. Exactly as pointed out in the post. https://github.com/sqlcipher/android-database-sqlcipher /issues/97.

Thanks draak567 for the insight. You are right we are getting in deadlcok often. Will keep posted.
Now we will see if we can remove all db access from MAIN thread, but this change will be humungous.

[dheerajb]

1. What I tried is disabled setLockingEnabled to false and then for synchronization purpose used Reentrant locks in android EmailProvider.java (In my app). Still I got a deadlock while acquiring lock().

@developernotes : We are working on if we can isolate the issue. But the issue happens with google implementation of Email on android, so currently finding it difficult to isolate.

2. I tried one more thing.
   deadlock was also happening on Map<String, SyncUpdateInfo> mSyncUpdateInfo. So I removed synchronized for mSyncUpdateInfo ans introduced Reentrant lock for that, but still no progress.

Can it be a dvm issue. Please see this link http://bugs.java.com/bugdatabase/view_bug.do?bug_id=6865591.

[dheerajb]

Hi

I made following changes to the the SQLitedatbase.java. But the issue still exists. Can you please verify if this is a valid change (though our issue not resolved)
Made this change throughout the file. Was thinking if in-case lock was acquired but never released.

orig:
public int getVersion() {
SQLiteStatement prog = null;
lock();
if (!isOpen()) {
throw new IllegalStateException("database not open");
}
try {
prog = new SQLiteStatement(this, "PRAGMA user_version;");
long version = prog.simpleQueryForLong();
return (int) version;
} finally {
if (prog != null) prog.close();
unlock();
}
}

change 👍
public int getVersion() {
SQLiteStatement prog = null;

    try {
       lock();
        if (!isOpen()) {
            throw new IllegalStateException("database not open");
        }
        prog = new SQLiteStatement(this, "PRAGMA user_version;");
        long version = prog.simpleQueryForLong();
        return (int) version;
    } finally {
        if (prog != null) prog.close();
        unlock();
    }
}

[dheerajb]

Hi draak567

were you able to solve the issue when you tried integrating AOSP Email with your app??

[developernotes]

Hi @dheerajb

Could you try removing the lock()/unlock() statments akin to the patch file supplied here, making the methods sychronized and run it through your scenario to see if there is any change in behavior? Thanks!

[dheerajb]

Hi @developernotes

I had tried this patch by @promeG , still we were in ANR.
Currently I am trying running SQLCiher in SingleThread support mode.
For this I am doing setLockingEnabled(false). This should disable Reentrant lock mechanism.
Further I am introducing synchronization on a object in our providers.

Now ANR is caused due to 👎

at java.lang.Object.wait(Native Method)

• waiting on <0x424f65b8> (a java.lang.VMThread) held by tid=26 (__eas[Exchange ActiveSync])

  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.lockForced(SQLiteDatabase.java:478)

  at net.sqlcipher.database.SQLiteDatabase.beginTransactionWithListener(SQLiteDatabase.java:587)

  at net.sqlcipher.database.SQLiteDatabase.beginTransaction(SQLiteDatabase.java:562)

[developernotes]

Hello @dheerajb

SQLCipher for Android is being complied with serialized threading mode, within the Java library however, I would be curious if you removed the various mLock.lock() and mLock.unlock() operations entirely how the application would behave. It sounds like the application may still be doing too much on the UI thread given the ANR.

[dheerajb]

Hi @developernotes

We tried disabling the locks by calling SQLiteDatabase::setLockingEnabled(false). But we were not able to completely remove the "mLock" dependency. Since, lockForced() is making use of the same, and also we observed calls like "mLock.getHoldCount()" in beginTransaction(). So, we were not able to comment out the mLock.

And also some times we observed that our UI was not updated. When we tried to analyze by collecting the dumpstate, we observed other threads (main thread was not involved) waiting for the lock (Similar to above pasted call stacks). UI was empty as the helper threads like Async tasks or Runnables which were trying to fetch data from the DB, were waiting on lock().

One point to note here is that we always dont get an ANR but our other threads/synctasks wait to acquire lock().

Any suggestions.
Thanks for your response

[dheerajb]

Hi @developernotes

Made the changes as suggested by you. Made sure we are building lib with serialized threading mode. Commented lock/unlock.

After that as soon as we launch our App we get this error:

04-04 12:16:30.722: D/dalvikvm(8331): Trying to load lib /data/data/com.android.email/lib/libsqlcipher_android.so 0x42a766a8
04-04 12:16:30.722: D/dalvikvm(8331): Shared lib '/data/data/com.android.email/lib/libsqlcipher_android.so' already loaded in same CL 0x42a766a8
04-04 12:16:30.722: D/dalvikvm(8331): Trying to load lib /data/data/com.android.email/lib/libdatabase_sqlcipher.so 0x42a766a8
04-04 12:16:30.722: D/dalvikvm(8331): Shared lib '/data/data/com.android.email/lib/libdatabase_sqlcipher.so' already loaded in same CL 0x42a766a8
04-04 12:16:30.722: I/ActivityThread(8331): Pub com.android.email.attachmentprovider: com.android.email.provider.AttachmentProvider
04-04 12:16:30.722: I/ActivityThread(8331): Pub com.android.exchange.directory.provider: com.android.exchange.provider.ExchangeDirectoryProvider
04-04 12:16:30.732: I/ActivityThread(8331): Pub aw_call_log: com.android.providers.contacts.CallLogProvider
04-04 12:16:30.732: I/ActivityThread(8331): Pub com.android.voicemail: com.android.providers.contacts.VoicemailContentProvider
04-04 12:16:30.732: I/dalvikvm(8331): Could not find method com.android.providers.contacts.VoicemailContentProvider.getCallingPackage, referenced from method com.android.providers.contacts.VoicemailContentProvider.getCallingPackageName
04-04 12:16:30.732: W/dalvikvm(8331): VFY: unable to resolve virtual method 31771: Lcom/android/providers/contacts/VoicemailContentProvider;.getCallingPackage ()Ljava/lang/String;
04-04 12:16:30.732: D/dalvikvm(8331): VFY: replacing opcode 0x6e at 0x0008
04-04 12:16:30.732: I/ActivityThread(8331): Pub com.android.social: com.android.providers.contacts.SocialProvider
04-04 12:16:30.732: I/ActivityThread(8331): Pub com.android.calendar.CalendarRecentSuggestionsProvider: com.android.calendar.CalendarRecentSuggestionsProvider
04-04 12:16:30.832: I/ContactsDatabaseHelper(8331): Bootstrapping database version: 623
04-04 12:16:30.922: I/Database(8331): sqlite returned: error code = 1, msg = statement aborts at 5: [ATTACH DATABASE ':memory:' AS presence_db;] cannot ATTACH database within transaction
04-04 12:16:30.922: E/Database(8331): Failure 1 (cannot ATTACH database within transaction) on 0x5f4fd540 when executing 'ATTACH DATABASE ':memory:' AS presence_db;'
04-04 12:16:30.922: I/Database(8331): sqlite returned: error code = 11, msg = database corruption at line 53343 of [118a3b3569]
04-04 12:16:30.922: I/Database(8331): sqlite returned: error code = 11, msg = database corruption at line 53382 of [118a3b3569]
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): Couldn't open contacts2.db for writing (will try read-only):
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): net.sqlcipher.database.SQLiteException: cannot ATTACH database within transaction: ATTACH DATABASE ':memory:' AS presence_db;
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at net.sqlcipher.database.SQLiteDatabase.native_execSQL(Native Method)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at net.sqlcipher.database.SQLiteDatabase.execSQL(SQLiteDatabase.java:1835)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at com.android.providers.contacts.ContactsDatabaseHelper.onOpen(ContactsDatabaseHelper.java:785)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at net.sqlcipher.database.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:132)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at net.sqlcipher.database.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:173)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at com.android.email.crypto.AWSQLiteOpenHelper.getReadableDatabase(AWSQLiteOpenHelper.java:53)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at com.android.providers.contacts.ContactsProvider2.initForDefaultLocale(ContactsProvider2.java:1518)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at com.android.providers.contacts.ContactsProvider2.performBackgroundTask(ContactsProvider2.java:1592)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at com.android.providers.contacts.ContactsProvider2$1.handleMessage(ContactsProvider2.java:1460)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at android.os.Handler.dispatchMessage(Handler.java:99)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at android.os.Looper.loop(Looper.java:137)
04-04 12:16:30.922: E/SQLiteOpenHelper(8331): at android.os.HandlerThread.run(HandlerThread.java:60)

[dheerajb]

@developernotes

It looks like mContentResolver.applyBatch is taking huge time and never releases the lock().
Other threads keep on waiting for the lock.
We are trying to break down our batch operations into chunk. Lets see how it goes.
Will keep you posted.

[illarionov]

@dheerajb, try to periodically execute SQLiteDatabase#yieldIfContendedSafely() to temporarily release the lock during long update transaction.

[ashishmo]

Did you figure out a solution to this issue? I am stuck with a very similar issue.

[MufriA]

@developernotes this issue is frequently reproduced in Lollipop, trying to isolate the root cause.

[ghost]

I also have the same issue too. :-( Did anyone figure this out??

[baskarsk]

Hi ,

I am getting the following Exception trace

"java.util.concurrent.TimeoutException: net.sqlcipher.database.SQLiteCompiledSql.finalize() timed out after 10 seconds"

I looked into the Sqlcipher code and found the Reentrantlock causing problem while the GC running.

Is there any way to fix this timeout issue?

Will the setLockingEnabled(false) & the yieldIfContendedSafely() will work ?

[developernotes]

Hello @baskarsk

Can you create a reproducible test in the SQLCipher for Android test suite?

[baskarsk]

@developernotes ,

Thanks for the reply,.

The issue is araising very rarely, i couldn't get the exact clue why it is happening. One debug scenario is , i left my device idle (Screen lock) for few hours and opening the app and doing a DB operation.

From the below link you could find the exact statment on timeout Exception in Idle state.(Which matches my scenario too)

"http://stackoverflow.com/questions/24021609/how-to-handle-java-util-concurrent-timeoutexception-android-os-binderproxy-fin"

Could you assist on this, meanwhile i run the Test Application and update on that.

[gccdChen]

Hi ,

I am getting the following Exception trace

"java.util.concurrent.TimeoutException: net.sqlcipher.database.SQLiteCompiledSql.finalize() timed out after 10 seconds"

If I use "android.databse.sqlite" then app run normally.

My Code:

db.beginTransaction();
for(...){// 40000+ records
  net.sqlcipher.database.SQLiteStatement sqLiteStatement  = db.compileStatement(sqlBuffer.toString());
  sqLiteStatement.executeInsert();
}
db.setTransactionSuccessful();
db.endTransaction();

[developernotes]

Hi @GUNC

The link that @baskarsk provided shows the Dalvik GC loop may likely be the cause of this. Since it appears you are inserting a rather large number of entries within a single transaction, you might consider batching those up into several smaller transactions to see if that helps address the issue.

[gccdChen]

Thanks @developernotes
batching those up into several smaller transactions can run normally!
Cipher cost more time then Android's Sqlite.

[developernotes]

Hi @GUNC

I'm glad to hear that worked!

[qiyongqiang]

Hi,@developernotes,i'm use net.zetetic:android-database-sqlcipher:3.5.1,sometimes we got anr,can you help me resolve the question,thanks.

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:1175)
at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:195)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:256)
at net.sqlcipher.database.SQLiteDatabase.lock(SQLiteDatabase.java:496)
at net.sqlcipher.database.SQLiteQuery.fillWindow(SQLiteQuery.java:64)
at net.sqlcipher.database.SQLiteCursor.fillWindow(SQLiteCursor.java:290)
at net.sqlcipher.database.SQLiteCursor.getCount(SQLiteCursor.java:271)
at net.sqlcipher.AbstractCursor.moveToPosition(AbstractCursor.java:178)
at net.sqlcipher.AbstractCursor.moveToFirst(AbstractCursor.java:222)
at android.database.CursorWrapper.moveToFirst(CursorWrapper.java:65)
at de.greenrobot.dao.AbstractDao.loadUnique(AbstractDao.java:154)
at de.greenrobot.dao.AbstractDao.loadUniqueAndCloseCursor(AbstractDao.java:147)
at de.greenrobot.dao.InternalQueryDaoAccess.loadUniqueAndCloseCursor(InternalQueryDaoAccess.java:25)
at de.greenrobot.dao.query.Query.unique(Query.java:118)

[developernotes]

Hi @qiyongqiang

What version of SQLCipher for Android are you using? Are you able to recreate the issue as a unit test within the SQLCipher for Android test suite?

[qiyongqiang]

@developernotes i'm use net.zetetic:android-database-sqlcipher:3.5.1, i can‘t recreate this issue as a unit test,this issue was found by bugly. are you some Suggestion？

[developernotes]

Hi @qiyongqiang

I am not aware of what would cause that error to occur in your case. It would require further information such as the query that is attempting to run at the time, which is why I suggested you attempt to recreate the issue within the test suite. Also, it appears you are using a wrapper around SQLCipher for Android, you might try to rule that out as well.