SQLCompileStatement crash DEMO #38

oleksandr-semenov · 2021-02-16T14:27:20Z

Added test to showcase crash on Android API 24-25 caused by java.util.concurrent.TimeoutException: net.sqlcipher.database.SQLiteCompiledSql.finalize() timed out after 10 seconds
Run the test and wait ~30 seconds.

Warning:
This test will crash the app.
I don't see a clean way of integrating this as an Action in the app. Instead, I suggest doing an Instrumented Android test

Original issue:
sqlcipher/android-database-sqlcipher#537

This test repeats Room behavior when it generates code for delete method:

  @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);
  }

developernotes · 2021-02-16T14:29:32Z

Hi @oleksandr-semenov

Thank you for this, we will review and provide feedback on this.

oleksandr-semenov · 2021-02-23T16:32:38Z

Hi @developernotes
Wondering have you had a chance to take a look at the test? Is there anything else I can help with?

developernotes · 2021-02-23T17:07:27Z

Hi @oleksandr-semenov

No, unfortunately I have not had an opportunity to review the test, however I hope to circle back to it later this week. I will provide an update once I've reviewed the scenario. Thanks!

developernotes · 2021-02-26T21:00:56Z

Hi @oleksandr-semenov

Are you only seeing this issue on Android 7/7.1, or elsewhere? I have been unable so far to restore a 7.1 image to a Pixel XL device for testing (i.e., OEM unlocking is disabled in developer settings). I did run this test 10 times on a Pixel 4 running Android 11, however, it does not fail there. If you could provide any information about the devices and OS's you are experiencing this on that would be helpful.

oleksandr-semenov · 2021-02-26T22:13:14Z

Hi @developernotes,
yes I'm seeing this issue only on 7/7.1. I haven't tested on the lower version as our app doesn't support them.
On OS version higher than 7.1 it doesn't crash.
I've used API 24 emulator for testing, could you try using it also to reproduce the issue?

oleksandr-semenov · 2021-03-03T16:28:15Z

Hi @developernotes
were you able to reproduce the issue using an emulator?
Is there anything else I can help you with?

developernotes · 2021-03-03T17:26:59Z

Hi @oleksandr-semenov

I have tried running this test repeatedly on an emulator using API 24, it is always successful for me. What ABI are you using for an emulator?

oleksandr-semenov · 2021-03-03T18:15:26Z

Hi @developernotes
I double-checked my test case and it's still crashing.
Emulator configuration is

Name: Pixel_4_API_24

CPU/ABI: Google Play Intel Atom (x86)

Target: google_apis_playstore [Google Play] (API level 24)

Skin: pixel_4

SD Card: 512M

fastboot.chosenSnapshotFile: 

runtime.network.speed: full

hw.accelerometer: yes

hw.device.name: pixel_4

hw.lcd.width: 1080

hw.initialOrientation: Portrait

image.androidVersion.api: 24

tag.id: google_apis_playstore

hw.mainKeys: no

hw.camera.front: emulated

avd.ini.displayname: Pixel 4 API 24

hw.gpu.mode: auto

hw.ramSize: 1536

PlayStore.enabled: true

fastboot.forceColdBoot: no

hw.cpu.ncore: 4

hw.keyboard: yes

hw.sensors.proximity: yes

hw.dPad: no

hw.lcd.height: 2280

vm.heapSize: 256

skin.dynamic: yes

hw.device.manufacturer: Google

hw.gps: yes

hw.audioInput: yes

image.sysdir.1: system-images\android-24\google_apis_playstore\x86\

showDeviceFrame: yes

hw.camera.back: virtualscene

AvdId: Pixel_4_API_24

hw.lcd.density: 440

hw.arc: false

hw.device.hash2: MD5:6b5943207fe196d842659d2e43022e20

fastboot.forceChosenSnapshotBoot: no

fastboot.forceFastBoot: yes

hw.trackBall: no

hw.battery: yes

hw.sdCard: yes

tag.display: Google Play

runtime.network.latency: none

disk.dataPartition.size: 6442450944

hw.sensors.orientation: yes

avd.ini.encoding: UTF-8

hw.gpu.enabled: yes

oleksandr-semenov · 2021-03-03T18:29:57Z

And on another image(x86_64) it also crashes, can't start armeabi emulator for some reason

Name: Pixel_4_XL_API_24_3

CPU/ABI: Google APIs Intel Atom (x86_64)

Target: google_apis [Google APIs] (API level 24)

Skin: pixel_4_xl

SD Card: 512M

fastboot.chosenSnapshotFile: 

runtime.network.speed: full

hw.accelerometer: yes

hw.device.name: pixel_4_xl

hw.lcd.width: 1440

hw.initialOrientation: Portrait

image.androidVersion.api: 24

tag.id: google_apis

hw.mainKeys: no

hw.camera.front: emulated

avd.ini.displayname: Pixel 4 XL API 24 3

hw.gpu.mode: auto

hw.ramSize: 1536

PlayStore.enabled: false

fastboot.forceColdBoot: no

hw.cpu.ncore: 4

hw.keyboard: yes

hw.sensors.proximity: yes

hw.dPad: no

hw.lcd.height: 3040

vm.heapSize: 256

skin.dynamic: yes

hw.device.manufacturer: Google

hw.gps: yes

hw.audioInput: yes

image.sysdir.1: system-images\android-24\google_apis\x86_64\

showDeviceFrame: yes

hw.camera.back: virtualscene

AvdId: Pixel_4_XL_API_24_3

hw.lcd.density: 560

hw.arc: false

hw.device.hash2: MD5:80326cf5b53c08af25d4243cb231faa9

fastboot.forceChosenSnapshotBoot: no

fastboot.forceFastBoot: yes

hw.trackBall: no

hw.battery: yes

hw.sdCard: yes

tag.display: Google APIs

runtime.network.latency: none

disk.dataPartition.size: 800M

hw.sensors.orientation: yes

avd.ini.encoding: UTF-8

hw.gpu.enabled: yes

maxkohne · 2021-03-03T18:37:37Z

I am also able to replicate the test crash.

2021-03-03 10:35:21.761 4997-5007/net.zetetic.sqlcipher.test E/AndroidRuntime: FATAL EXCEPTION: FinalizerWatchdogDaemon
    Process: net.zetetic.sqlcipher.test, PID: 4997
    java.util.concurrent.TimeoutException: net.sqlcipher.database.SQLiteCompiledSql.finalize() timed out after 10 seconds
        at java.lang.Object.wait(Native Method)
        at java.lang.Thread.parkFor$(Thread.java:2127)
        at sun.misc.Unsafe.park(Unsafe.java:325)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:161)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:840)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:873)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
        at net.sqlcipher.database.SQLiteDatabase.lock(SQLiteDatabase.java:570)
        at net.sqlcipher.database.SQLiteCompiledSql.releaseSqlStatement(SQLiteCompiledSql.java:104)
        at net.sqlcipher.database.SQLiteCompiledSql.finalize(SQLiteCompiledSql.java:146)
        at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:222)
        at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:209)
        at java.lang.Thread.run(Thread.java:761)

developernotes · 2021-03-03T20:33:17Z

Hi @oleksandr-semenov

Puzzling, my emulator details appear to mirror your almost identically (I've only removed the extraneous newlines below).

Name: api-24-x86
CPU/ABI: Google Play Intel Atom (x86)
Path: /Users/nparker/.android/avd/api-24-x86.avd
Target: google_apis_playstore [Google Play] (API level 24)
Skin: pixel_4
SD Card: 512M
fastboot.chosenSnapshotFile: 
runtime.network.speed: full
hw.accelerometer: yes
hw.device.name: pixel_4
hw.lcd.width: 1080
hw.initialOrientation: Portrait
image.androidVersion.api: 24
tag.id: google_apis_playstore
hw.mainKeys: no
hw.camera.front: emulated
avd.ini.displayname: api-24-x86
hw.gpu.mode: auto
hw.ramSize: 1536
PlayStore.enabled: true
fastboot.forceColdBoot: no
hw.cpu.ncore: 4
hw.keyboard: yes
hw.sensors.proximity: yes
hw.dPad: no
hw.lcd.height: 2280
vm.heapSize: 256
skin.dynamic: yes
hw.device.manufacturer: Google
hw.gps: yes
hw.audioInput: yes
image.sysdir.1: system-images/android-24/google_apis_playstore/x86/
showDeviceFrame: yes
hw.camera.back: virtualscene
AvdId: api-24-x86
hw.lcd.density: 440
hw.arc: false
hw.device.hash2: MD5:6b5943207fe196d842659d2e43022e20
fastboot.forceChosenSnapshotBoot: no
fastboot.forceFastBoot: yes
hw.trackBall: no
hw.battery: yes
hw.sdCard: yes
tag.display: Google Play
runtime.network.latency: none
disk.dataPartition.size: 6442450944
hw.sensors.orientation: yes
avd.ini.encoding: UTF-8
hw.gpu.enabled: yes

oleksandr-semenov · 2021-03-03T20:47:43Z

I don't even know what else can be different.
Emulator version is

I can reproduce this 100% times on Mac and Windows.

maxkohne · 2021-03-03T20:52:23Z

I was unable to checkout @oleksandr-semenov's branch so instead i just cloned this repo and copied / pasted the two file changes from this pull request.

I then made a new emulator with API 24.

Then clicked "Run Behavior Test Suite" in the app after it built with that one new file (SQLCompileStatementFinalizeTest.java) and the edited file (TestSuiteRunner.java).

Those are all the steps I took to replicate.

EDIT: When i cloned the project, it was requiring 4.2.0-beta04 rather than the current stable 4.1.2 for classpath 'com.android.tools.build:gradle. I am using the stable version of studio to build so i changed that line in build.gradle to 4.1.2

brodycj · 2021-04-06T19:25:29Z

FYI here is how I checked out the @oleksandr-semenov branch:

git remote add o https://github.com/oleksandr-semenov/sqlcipher-android-tests (followed the link to the branch at the top, then copied the project URL from the project page)
git fetch o sql_lite_compile_statement_crash
git checkout sql_lite_compile_statement_crash

When I run the app from Android Studio, it crashes consistently on both emulator and my Android 7.0 device (Samsung Galaxy S6 for Verizon 4G). I made my emulator is a Pixel 2 x86 emulator with API 24, would be happy to provide more details or trying on another emulator build if needed.

Here is some trace output from my Android 7.0 (API 24) emulator:

2021-04-06 14:39:26.638 2608-2623/net.zetetic.sqlcipher.test W/OpenGLRenderer: Failed to choose config with EGL_SWAP_BEHAVIOR_PRESERVED, retrying without...
2021-04-06 14:39:26.638 2608-2623/net.zetetic.sqlcipher.test D/OpenGLRenderer: Swap behavior 0
2021-04-06 14:39:26.758 2608-2623/net.zetetic.sqlcipher.test D/EGL_emulation: eglCreateContext: 0xa8685120: maj 3 min 0 rcv 3
2021-04-06 14:39:26.762 2608-2623/net.zetetic.sqlcipher.test D/EGL_emulation: eglMakeCurrent: 0xa8685120: ver 3 0 (tinfo 0xa86834d0)
2021-04-06 14:39:26.764 2608-2623/net.zetetic.sqlcipher.test E/eglCodecCommon: glUtilsParamSize: unknow param 0x00008cdf
2021-04-06 14:39:26.764 2608-2623/net.zetetic.sqlcipher.test E/eglCodecCommon: glUtilsParamSize: unknow param 0x00008824
2021-04-06 14:39:26.786 2608-2623/net.zetetic.sqlcipher.test D/EGL_emulation: eglMakeCurrent: 0xa8685120: ver 3 0 (tinfo 0xa86834d0)
2021-04-06 14:39:30.336 2608-2608/net.zetetic.sqlcipher.test I/Choreographer: Skipped 237 frames!  The application may be doing too much work on its main thread.
2021-04-06 14:39:52.082 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: onCreate
2021-04-06 14:39:52.448 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test suite on x86 platform
2021-04-06 14:39:52.561 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:Finalize SQLComileStatement causes crash on API 24-25
2021-04-06 14:39:52.561 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before prepareDatabaseEnvironment
2021-04-06 14:39:52.561 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment
2021-04-06 14:39:52.562 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath
2021-04-06 14:39:52.563 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path
2021-04-06 14:39:52.563 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before getDatabasePath
2021-04-06 14:39:52.564 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before createDatabase
2021-04-06 14:39:52.564 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before ZeteticApplication.getInstance().createDatabase
2021-04-06 14:39:52.564 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase
2021-04-06 14:39:52.564 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase
2021-04-06 14:39:55.634 2608-2608/net.zetetic.sqlcipher.test I/Choreographer: Skipped 215 frames!  The application may be doing too much work on its main thread.
2021-04-06 14:39:56.837 2608-2608/net.zetetic.sqlcipher.test I/Choreographer: Skipped 70 frames!  The application may be doing too much work on its main thread.
2021-04-06 14:39:57.010 2608-2623/net.zetetic.sqlcipher.test D/EGL_emulation: eglMakeCurrent: 0xa8685120: ver 3 0 (tinfo 0xa86834d0)
2021-04-06 14:39:58.062 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before setUp
2021-04-06 14:40:10.274 2608-2619/net.zetetic.sqlcipher.test I/art: Background sticky concurrent mark sweep GC freed 404740(3MB) AllocSpace objects, 1(64KB) LOS objects, 44% free, 4MB/8MB, paused 273us total 211.253ms
2021-04-06 14:40:30.796 2608-2614/net.zetetic.sqlcipher.test I/art: Thread[3,tid=2614,WaitingInMainSignalCatcherLoop,Thread*=0xa5e70e00,peer=0x12c2e790,"Signal Catcher"]: reacting to signal 3
2021-04-06 14:40:30.933 2608-2614/net.zetetic.sqlcipher.test I/art: Wrote stack traces to '/data/anr/traces.txt'
    
    --------- beginning of crash
2021-04-06 14:40:35.823 2608-2618/net.zetetic.sqlcipher.test E/AndroidRuntime: FATAL EXCEPTION: FinalizerWatchdogDaemon
    Process: net.zetetic.sqlcipher.test, PID: 2608
    java.util.concurrent.TimeoutException: net.sqlcipher.database.SQLiteCompiledSql.finalize() timed out after 10 seconds
        at java.lang.Object.wait(Native Method)
        at java.lang.Thread.parkFor$(Thread.java:2127)
        at sun.misc.Unsafe.park(Unsafe.java:325)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:161)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:840)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:873)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
        at net.sqlcipher.database.SQLiteDatabase.lock(SQLiteDatabase.java:570)
        at net.sqlcipher.database.SQLiteCompiledSql.releaseSqlStatement(SQLiteCompiledSql.java:104)
        at net.sqlcipher.database.SQLiteCompiledSql.finalize(SQLiteCompiledSql.java:146)
        at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:222)
        at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:209)
        at java.lang.Thread.run(Thread.java:761)
2021-04-06 14:40:36.446 2608-2623/net.zetetic.sqlcipher.test D/EGL_emulation: eglMakeCurrent: 0xa8685120: ver 3 0 (tinfo 0xa86834d0)
2021-04-06 14:40:48.468 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Test complete: Finalize SQLComileStatement causes crash on API 24-25 ran in 50.40 seconds using library version 4.4.2
2021-04-06 14:40:48.497 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:SummingStepTest Test
2021-04-06 14:40:48.501 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before prepareDatabaseEnvironment
2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment
2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath
2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path
2021-04-06 14:40:48.502 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: Finalize SQLComileStatement causes crash on API 24-25 - success:true
2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before getDatabasePath
2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before createDatabase
2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before ZeteticApplication.getInstance().createDatabase
2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase
2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase
2021-04-06 14:40:48.866 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before setUp
2021-04-06 14:40:50.965 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Test complete: SummingStepTest Test ran in 2.10 seconds using library version 4.4.2
2021-04-06 14:40:50.966 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: SummingStepTest Test - success:true
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:JSON cast test
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before prepareDatabaseEnvironment
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before getDatabasePath
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before createDatabase
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before ZeteticApplication.getInstance().createDatabase
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase
2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase
2021-04-06 14:40:51.020 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before setUp
2021-04-06 14:40:51.022 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Test complete: JSON cast test ran in 0.00 seconds using library version 4.4.2
2021-04-06 14:40:51.023 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: JSON cast test - success:true
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:Simple Query Test
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before prepareDatabaseEnvironment
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before getDatabasePath
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before createDatabase
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before ZeteticApplication.getInstance().createDatabase
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase
2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase
2021-04-06 14:40:51.073 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before setUp
2021-04-06 14:40:52.025 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Test complete: Simple Query Test ran in 0.95 seconds using library version 4.4.2
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:null
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before prepareDatabaseEnvironment
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before getDatabasePath
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before createDatabase
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before ZeteticApplication.getInstance().createDatabase
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase
2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase
2021-04-06 14:40:52.026 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: Simple Query Test - success:true
2021-04-06 14:40:52.088 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before setUp
2021-04-06 14:40:52.092 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Building database with 10,000 rows, 1 columns
2021-04-06 14:40:52.095 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Generated column name:a for index:0
2021-04-06 14:42:04.483 2608-2619/net.zetetic.sqlcipher.test I/art: Background partial concurrent mark sweep GC freed 767(21KB) AllocSpace objects, 154(3MB) LOS objects, 39% free, 4MB/7MB, paused 112us total 124.443ms
2021-04-06 14:42:26.498 2608-2619/net.zetetic.sqlcipher.test I/art: Background partial concurrent mark sweep GC freed 762(21KB) AllocSpace objects, 153(2MB) LOS objects, 40% free, 4MB/7MB, paused 112us total 498.071ms

I do find it very interesting that there is some trace output after the point of the crash.

When I ran it on my Samsung Galaxy S6 with Android 7.0, it crashed but then I saw from logcat that the test suite actually ran and finished with 119 passed and 0 failed tests.

We should be able to use BrowserStack (browserstack.com) to run on some Android 7 devices, they seem to offer free plans for open source projects.

alla2040 · 2021-04-07T16:05:31Z

I also can reproduce the crash from the test of @oleksandr-semenov and not only with API 25 (Nexus 5) emulator in Android Studio, but also with Android 10 API 29 (Pixel 3) emulator: java.util.concurrent.TimeoutException: net.sqlcipher.database.SQLiteCompiledSql.finalize() timed out after 10 seconds
As for devices models in Crashlytics: I see this crash in Samsung, Huawei, Sony and many other devices.
@developernotes maybe you have any update on this?

oleksandr-semenov · 2021-06-11T12:18:21Z

@developernotes
I've updated tests with locking enabled/disabled versions.
It constantly crashes for me on the emulator(API 25)

Name: Pixel_4_XL_API_25 
CPU/ABI: Google APIs Intel Atom (x86) 
Path: .android\avd\Pixel_4_XL_API_25.avd Target: google_apis [Google APIs] (API level 25) 
Skin: pixel_4_xl 
SD Card: 512M 
fastboot.chosenSnapshotFile: runtime.network.speed: full 
hw.accelerometer: yes 
hw.device.name: pixel_4_xl 
hw.lcd.width: 1440 
hw.initialOrientation: Portrait 
image.androidVersion.api: 25

1st test has locking set to false and, as expected, works fine.
2nd has locking set to true and crashes

Try also looking in the log output. You should see this crash:

  Process: net.zetetic.sqlcipher.test, PID: 6405
    java.util.concurrent.TimeoutException: net.sqlcipher.database.SQLiteCompiledSql.finalize() timed out after 10 seconds
        at java.lang.Object.wait(Native Method)
        at java.lang.Thread.parkFor$(Thread.java:2127)
        at sun.misc.Unsafe.park(Unsafe.java:325)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:161)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:840)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:873)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
        at net.sqlcipher.database.SQLiteDatabase.lock(SQLiteDatabase.java:570)
        at net.sqlcipher.database.SQLiteCompiledSql.releaseSqlStatement(SQLiteCompiledSql.java:104)
        at net.sqlcipher.database.SQLiteCompiledSql.finalize(SQLiteCompiledSql.java:146)
        at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:222)
        at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:209)
        at java.lang.Thread.run(Thread.java:761)

I don't know how to make it not crash on API <=25

I also use Android Studio to build the project and launch it. Maybe you could try doing this also?

developernotes · 2021-06-17T19:08:19Z

Hello @oleksandr-semenov

Thank you for your follow-up. Internally we have been doing some work on SQLCipher for Android to extend disabling of the locking with the library and have been evaluating your test scenario in that context. When locking is enabled, your test creates a scenario where the ReentrantLock is acquired on one thread, while the other thread is blocked from execution when the finalizer attempts to invoke releaseSqlStatement(), awaiting the release of the lock from the other thread. Eventually you reach the timeout exception.

Can you tell us a bit more about the threading environment within your application, and how those threads interface with SQLCipher for Android for both read and write operations?

oleksandr-semenov · 2021-06-18T07:01:19Z

Hi @developernotes

Thanks for continue looking into this issue.

I found one new thing. A single test run on API >=26 didn't crash before. However, when I do a sequence of tests with locking set to false and true, it crashes any OS. This means that it can create problems for any OS, as @alla2040 reported previously.

It's definitely a multithreading problem. My thoughts on the crash reason are that:

SQLiteCompiledSql finalize calls releaseSqlStatement(this will be called essentially by GC)
releaseSqlStatement is blocked due to some reason and most likely because of another long-running transaction(in fact, finalize is also blocked, preventing the object from GCing)
Old finalizer watchdog or even latest throws an exception when finalization has timed out(>10 sec) and we have a crash. So I think finalize is not a suitable place for doing thread locking.

Our app does a lot of concurrent DB calls, and most of them are transactional. Even though transactions could be relatively quick, there might be many of them queued already, which will sum up to more than 10s of blocking time. This issue doesn't reproduce when we use Room/SQLite without encryption.

My test replicates the case, and you can treat it as a set of stages:

Create an SQL statement that will be finalized and will call releaseSqlStatement. We need 2 of them at least because the first one will be cached internally in DB.
Start blocking transaction that runs long (~30-40s). This should be done in a parallel thread.
Try causing GC so that finalize is called for SQL statement.

Let me know if I can help more.

developernotes · 2021-07-08T22:00:01Z

Hi @oleksandr-semenov

I have just pushed up a change to the master branch that removes the locking behavior within the finalizer of SQLiteCompiledSql, we will include that in the next release. Thanks!

shiita0903 · 2021-08-02T17:05:23Z

Hi @developernotes

Thank you for your fixing the issue.
When will you release it? Please let me know if you have a release plan. I really want the next release.

developernotes · 2021-08-02T19:24:42Z

Hi @shiita0903,

This will be officially bundled with the next public SQLCipher core release. While we do not have a specific release date available, should you need it now, you are welcome to build the library from source based on the master branch and use it now.

himanshubakshi · 2021-09-06T05:17:47Z

Hi, any update on when this would br released? This is impacting our app.

developernotes · 2021-09-07T12:19:21Z

Hi @himanshubakshi,

No, we do not have a planned release date for the next version of SQLCipher yet. You may always consider the suggestions here to build from source to utilize a newer build.

CristianCardosoArellano · 2023-09-09T02:08:34Z

Is this still active bug ?

CristianCardosoArellano · 2023-09-09T02:22:10Z

Is this still active bug ?

developernotes · 2023-09-11T12:18:03Z

Hello @cristiancardosodexcom,

Not that I am aware of, it would be best for @oleksandr-semenov to comment. Please note the android-database-sqlcipher library is deprecated, detailed here, with sqlcipher-android as the long-term replacement.

oleksandr-semenov added 2 commits February 16, 2021 16:13

Demo of crash

a3b25ac

Rename

de88080

oleksandr-semenov mentioned this pull request Feb 16, 2021

java.util.concurrent.TimeoutException: net.sqlcipher.database.SQLiteCompiledSql.finalize() timed out after 10 seconds sqlcipher/android-database-sqlcipher#537

Closed

Updated tests with locking and non-locking versions

92acbf1

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

SQLCompileStatement crash DEMO #38

SQLCompileStatement crash DEMO #38

oleksandr-semenov commented Feb 16, 2021 •

edited

Loading

developernotes commented Feb 16, 2021

oleksandr-semenov commented Feb 23, 2021

developernotes commented Feb 23, 2021

developernotes commented Feb 26, 2021

oleksandr-semenov commented Feb 26, 2021

oleksandr-semenov commented Mar 3, 2021

developernotes commented Mar 3, 2021

oleksandr-semenov commented Mar 3, 2021

oleksandr-semenov commented Mar 3, 2021 •

edited

Loading

maxkohne commented Mar 3, 2021

developernotes commented Mar 3, 2021

oleksandr-semenov commented Mar 3, 2021

maxkohne commented Mar 3, 2021 •

edited

Loading

brodycj commented Apr 6, 2021

alla2040 commented Apr 7, 2021

oleksandr-semenov commented Jun 11, 2021 •

edited

Loading

developernotes commented Jun 17, 2021

oleksandr-semenov commented Jun 18, 2021 •

edited

Loading

developernotes commented Jul 8, 2021

shiita0903 commented Aug 2, 2021

developernotes commented Aug 2, 2021

himanshubakshi commented Sep 6, 2021

developernotes commented Sep 7, 2021

CristianCardosoArellano commented Sep 9, 2023

CristianCardosoArellano commented Sep 9, 2023

developernotes commented Sep 11, 2023

SQLCompileStatement crash DEMO #38

Are you sure you want to change the base?

SQLCompileStatement crash DEMO #38

Conversation

oleksandr-semenov commented Feb 16, 2021 • edited Loading

developernotes commented Feb 16, 2021

oleksandr-semenov commented Feb 23, 2021

developernotes commented Feb 23, 2021

developernotes commented Feb 26, 2021

oleksandr-semenov commented Feb 26, 2021

oleksandr-semenov commented Mar 3, 2021

developernotes commented Mar 3, 2021

oleksandr-semenov commented Mar 3, 2021

oleksandr-semenov commented Mar 3, 2021 • edited Loading

maxkohne commented Mar 3, 2021

developernotes commented Mar 3, 2021

oleksandr-semenov commented Mar 3, 2021

maxkohne commented Mar 3, 2021 • edited Loading

brodycj commented Apr 6, 2021

alla2040 commented Apr 7, 2021

oleksandr-semenov commented Jun 11, 2021 • edited Loading

developernotes commented Jun 17, 2021

oleksandr-semenov commented Jun 18, 2021 • edited Loading

developernotes commented Jul 8, 2021

shiita0903 commented Aug 2, 2021

developernotes commented Aug 2, 2021

himanshubakshi commented Sep 6, 2021

developernotes commented Sep 7, 2021

CristianCardosoArellano commented Sep 9, 2023

CristianCardosoArellano commented Sep 9, 2023

developernotes commented Sep 11, 2023

oleksandr-semenov commented Feb 16, 2021 •

edited

Loading

oleksandr-semenov commented Mar 3, 2021 •

edited

Loading

maxkohne commented Mar 3, 2021 •

edited

Loading

oleksandr-semenov commented Jun 11, 2021 •

edited

Loading

oleksandr-semenov commented Jun 18, 2021 •

edited

Loading