SQLCompileStatement crash DEMO

[oleksandr-semenov]

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]

Hi @oleksandr-semenov

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

[oleksandr-semenov]

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

[developernotes]

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]

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]

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]

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

[developernotes]

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]

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]

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]

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]

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]

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

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

[maxkohne]

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

[brody4hire]

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 02021-04-06 14:39:26.758 2608-2623/net.zetetic.sqlcipher.test D/EGL_emulation: eglCreateContext: 0xa8685120: maj 3 min 0 rcv 32021-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 0x00008cdf2021-04-06 14:39:26.764 2608-2623/net.zetetic.sqlcipher.test E/eglCodecCommon: glUtilsParamSize: unknow param 0x000088242021-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: onCreate2021-04-06 14:39:52.448 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test suite on x86 platform2021-04-06 14:39:52.561 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:Finalize SQLComileStatement causes crash on API 24-252021-04-06 14:39:52.561 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before prepareDatabaseEnvironment2021-04-06 14:39:52.561 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment2021-04-06 14:39:52.562 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath2021-04-06 14:39:52.563 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path2021-04-06 14:39:52.563 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before getDatabasePath2021-04-06 14:39:52.564 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before createDatabase2021-04-06 14:39:52.564 2608-2636/net.zetetic.sqlcipher.test I/SQLCompileStatementFinalizeTest: Before ZeteticApplication.getInstance().createDatabase2021-04-06 14:39:52.564 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase2021-04-06 14:39:52.564 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase2021-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 setUp2021-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.253ms2021-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 32021-04-06 14:40:30.933 2608-2614/net.zetetic.sqlcipher.test I/art: Wrote stack traces to '/data/anr/traces.txt' --------- beginning of crash2021-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.22021-04-06 14:40:48.497 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:SummingStepTest Test2021-04-06 14:40:48.501 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before prepareDatabaseEnvironment2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path2021-04-06 14:40:48.502 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: Finalize SQLComileStatement causes crash on API 24-25 - success:true2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before getDatabasePath2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before createDatabase2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before ZeteticApplication.getInstance().createDatabase2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase2021-04-06 14:40:48.502 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase2021-04-06 14:40:48.866 2608-2636/net.zetetic.sqlcipher.test I/SummingStepTest: Before setUp2021-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.22021-04-06 14:40:50.966 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: SummingStepTest Test - success:true2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:JSON cast test2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before prepareDatabaseEnvironment2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before getDatabasePath2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before createDatabase2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before ZeteticApplication.getInstance().createDatabase2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase2021-04-06 14:40:50.968 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase2021-04-06 14:40:51.020 2608-2636/net.zetetic.sqlcipher.test I/JsonCastTest: Before setUp2021-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.22021-04-06 14:40:51.023 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: JSON cast test - success:true2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:Simple Query Test2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before prepareDatabaseEnvironment2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before getDatabasePath2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before createDatabase2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before ZeteticApplication.getInstance().createDatabase2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase2021-04-06 14:40:51.023 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase2021-04-06 14:40:51.073 2608-2636/net.zetetic.sqlcipher.test I/SimpleQueryTest: Before setUp2021-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.22021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Running test:null2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before prepareDatabaseEnvironment2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered prepareDatabaseEnvironment2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before getDatabasePath2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before mkdirs on parent of database path2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before getDatabasePath2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before createDatabase2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before ZeteticApplication.getInstance().createDatabase2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Entered ZeteticApplication::createDatabase2021-04-06 14:40:52.026 2608-2636/net.zetetic.sqlcipher.test I/Zetetic: Before SQLiteDatabase.openOrCreateDatabase2021-04-06 14:40:52.026 2608-2608/net.zetetic.sqlcipher.test I/TestSuiteBehaviorsActivity: Simple Query Test - success:true2021-04-06 14:40:52.088 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Before setUp2021-04-06 14:40:52.092 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Building database with 10,000 rows, 1 columns2021-04-06 14:40:52.095 2608-2636/net.zetetic.sqlcipher.test I/DefaultCursorWindowAllocationTest: Generated column name:a for index:02021-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.443ms2021-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]

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]

@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]

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]

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:

• SQLiteCompiledSqlfinalize 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:

1. 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.
2. Start blocking transaction that runs long (~30-40s). This should be done in a parallel thread.
3. Try causing GC so that finalize is called for SQL statement.

Let me know if I can help more.

[developernotes]

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]

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]

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]

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

[developernotes]

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.

[CrisCard0so]

Is this still active bug ?

[CrisCard0so]

Is this still active bug ?

[developernotes]

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.