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

[oleksandr-semenov]

Expected Behavior

App doesn't crash

Actual Behavior

App crashes due to SQLiteCipher on Android API 24-25

Steps to Reproduce

App uses Room + SQLCipher.
WAL is enabled.

The only synthetic case how I can emulate crash is accessing SQLiteCompiledSql(Use API 24-25 Android emulator):

1. Launch thread A
2. Launch thread B
3. Block B, In A create SQLiteCompiledSql object, set nStatement so that finalize can run releaseSqlStatement, block A, unblock B
4. In B launch start a long transaction, unblock A, do memory extensive work to cause GC
5. Wait

Android test Kotlin code(if required I can convert to Java):

  @Test
    fun emulateCrash() = coroutineRule.runBlocking {
        dbRule.useWithProject {
            val latch1 = CountDownLatch(1)
            val latch2 = CountDownLatch(1)

            launch (Dispatchers.IO) {
                SQLiteProxy(db.openHelper.writableDatabase as SQLiteDatabase, "SELECT 1 FROM Album").setupStub()
                latch2.countDown()
                latch1.await()
            }

            latch2.await()
            db.withTransaction {
                latch1.countDown()
                while (true) {
                    // no matter what  - just pollute memory to cause GC
                    val albumEntity = newAlbum(
                        projectEntity = projectEntity,
                        companyEntity = companyEntity
                    )
                }
            }
        }
    }

package net.sqlcipher.database;

public class SQLiteProxy extends SQLiteCompiledSql {

    public SQLiteProxy(SQLiteDatabase db, String sql) {
        super(db, sql);
    }

    public void setupStub() {
        nStatement = Long.MAX_VALUE;
    }

}

SQLCipher version (can be identified by executing PRAGMA cipher_version;):
4.4.2 community

SQLCipher for Android version:
4.4.2

Room version:
2.3.0-beta01

My guess would be how Android handles GC and especially finalize() on version API 24-25.
Since there is DB lock() call that blocks/await thread this causes watchdog to throw exception.
I've checked generated Room code and I don't see where the cursor can be not closed.
Not sure when the compiled statement is not cached to emulate the scenario.
However, it happens in normal code execution with extensive concurrent work and multiple transactions.

Can releaseSqlStatement be removed from finalize or handled in a different way?

[developernotes]

Hi @oleksandr-semenov

Thanks for sharing this. By chance have you tried to integrate this scenario within the SQLCipher for Android test suite? It might streamline both verification and testing of any changes made to address the issue. Thanks!

[oleksandr-semenov]

Hi @developernotes will try doing that. Should I open PR with the test?

[developernotes]

Hi @oleksandr-semenov

Excellent, that would be great. Thanks!

[oleksandr-semenov]

Now I know how to reproduce this using Room.

Requirements:
Use Android API 24-25

Steps:
Make a statement for DAO like

    @Query("DELETE FROM XXX WHERE id IN (:ids)")
    abstract suspend fun deleteXXX(ids: List<Long>): Int

Seems that this query doesn't work with Cursor. Hence, cursor.close() will not be called.
Room generated code:

 @Override
  public Object deleteXXX(final List<Long> localIds,
      final Continuation<? super Integer> p1) {
    return CoroutinesRoom.execute(__db, true, new Callable<Integer>() {
      @Override
      public Integer call() throws Exception {
        StringBuilder _stringBuilder = StringUtil.newStringBuilder();
        _stringBuilder.append("DELETE FROM XXX WHERE local_id IN (");
        final int _inputSize = localIds.size();
        StringUtil.appendPlaceholders(_stringBuilder, _inputSize);
        _stringBuilder.append(")");
        final String _sql = _stringBuilder.toString();
        final SupportSQLiteStatement _stmt = __db.compileStatement(_sql);
        int _argIndex = 1;
        for (Long _item : localIds) {
          if (_item == null) {
            _stmt.bindNull(_argIndex);
          } else {
            _stmt.bindLong(_argIndex, _item);
          }
          _argIndex ++;
        }
        __db.beginTransaction();
        try {
          final java.lang.Integer _result = _stmt.executeUpdateDelete();
          __db.setTransactionSuccessful();
          return _result;
        } finally {
          __db.endTransaction();
        }
      }
    }, p1);
  }

Make X times calls of this function(X >= 2).
X >= 2 because the first statement will be cached, which means not accessible for GC. But second will be checked by SQLiteDatabase cache and omitted(accessible for GC)

Right after execution in another thread/method run transaction that runs > 10 sec and do memory intensive job.
Observer exception.

What happens:

1. App runs 2 queries, 1st SQLiteCompiledSql is cached, 2nd is available for GC
2. In another method/thread transaction runs for a long and blocks DB
3. When GC starts and tries to free memory from 2nd statement it calls finalize()
4. finalize() awaits the end of the transaction(s) because of release method call that attempts to acquire the lock for DB
5. In 10-30 sec demon watchdog throws an exception

I'll try to add this to your test suite, not sure if I need this whole test or just emulating available for GC SQLiteCompiledSql is enough

[developernotes]

Hi @oleksandr-semenov

That is a great find! Having this within the test suite would be excellent, please let us know if you run into any troubles.

[oleksandr-semenov]

@developernotes I've created PR sqlcipher/sqlcipher-android-tests#38

[developernotes]

Hi @oleksandr-semenov

We will look into the reported issue, thank you!

[praveenb]

I see this crash issue happening, when inserting 15000 rows CSV files data. It worked fine with inserting 500 rows in a CSV file.

Thanks

[alla2040]

@developernotes
@oleksandr-semenov
I also face this crash for a long time. Also use Room. And I don't insert several thousand rows (as was described by @praveenb ), ordinary work with the database, very few entries.
I tried to fix it by replacing lock() with tryLock() when locking the database SQLiteDatabase in sqlcipher java code (I compiled sqlcipher lib by myself into .so-files instead of import the lib directly in build.gradle in order to try to fix the crash). It seems to me that it worked. At least I don't see this crash in Crashlytics anymore, but the other two crashes appeared:

1. net.sqlcipher.database.SQLiteDatabase - Fatal Exception: net.sqlcipher.database.SQLiteException cannot start a transaction within a transaction: BEGIN EXCLUSIVE
2. net.sqlcipher.database.SQLiteCompiledSql - Fatal Exception: net.sqlcipher.database.SQLiteException file is not a database: , while compiling: select count(*) from sqlite_master

This crash I also see in Android 10 devices

[srb9181]

@developernotes Is there any updates on this issue ? Because of this issue now our app user facing usability issues.

[stale]

Hello, it looks like there has been no activity on this issue recently. Has the issue been fixed, or does it still require the community's attention? This issue may be closed if no further activity occurs. You may also label this issue as "bug", "enhancement", or "security" and I will leave it open. Thank you for your contributions.