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.

[oleksandr-semenov]

Hi @developernotes
This is an issue for us still and seems for other developers also. Are there any plans to fix it?

[developernotes]

Hello @oleksandr-semenov

Unfortunately, I have still been unable to reproduce this in any emulator on my host machine. Since you are able to reproduce it, would you try a modification to your test scenario to see if the same or different behavior is observed? In your test scenario where you are able to reproduce the issue, after constructing the SQLiteDatabase instance, call setLockingEnabled(false) on the connection. I'm curious if you still experience the issue.

[oleksandr-semenov]

Ok I will try doing that and will let you know.

[oleksandr-semenov]

@developernotes I've updated my test PR. Please take a look.

[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.

[alla2040]

hi, the issue is not fixed, it still requires the attention.

[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.

[stale]

Closing this issue after a prolonged period of inactivity. If this issue is still present in the latest release, please feel free to reopen with up-to-date information.

[lalchand92]

This issue seems to be closed due to inactivity but issue still persist for us. @developernotes can you please provide update here?

[developernotes]

Hi @lalchand92,

A change was pushed to master on July 8, 2021 to remove the locking within the finalizer of SQLiteCompiledSql. Would you please build this locally and let us know if it resolves your issue?

[parasgupta93]

@developernotes I am still seeing this issue in 4.5.2 version. Looks like still issue exist.

[developernotes]

Hello @parasgupta93,

Would you open a new ticket with specific details about what your application is doing which causes the error? Additionally, please review the questions in the template as that will help diagnose the issue.