Connection pool closing causing app crash

zkrige commented 1 year ago

java.lang.RuntimeException: An error occurred while executing doInBackground() at androidx.loader.content.ModernAsyncTask$3.done(ModernAsyncTask.java:164) at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:383) at java.util.concurrent.FutureTask.setException(FutureTask.java:252) at java.util.concurrent.FutureTask.run(FutureTask.java:271) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) at java.lang.Thread.run(Thread.java:920) Caused by: java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed. at net.zetetic.database.sqlcipher.SQLiteConnectionPool.throwIfClosedLocked(SQLiteConnectionPool.java:973) at net.zetetic.database.sqlcipher.SQLiteConnectionPool.waitForConnection(SQLiteConnectionPool.java:688) at net.zetetic.database.sqlcipher.SQLiteConnectionPool.acquireConnection(SQLiteConnectionPool.java:359) at net.zetetic.database.sqlcipher.SQLiteSession.acquireConnection(SQLiteSession.java:929) at net.zetetic.database.sqlcipher.SQLiteSession.executeForCursorWindow(SQLiteSession.java:869) at net.zetetic.database.sqlcipher.SQLiteQuery.fillWindow(SQLiteQuery.java:66) at net.zetetic.database.sqlcipher.SQLiteCursor.fillWindow(SQLiteCursor.java:196) at net.zetetic.database.sqlcipher.SQLiteCursor.getCount(SQLiteCursor.java:135) at android.content.ContentResolver.query(ContentResolver.java:1238) at android.content.ContentResolver.query(ContentResolver.java:1151)

zkrige commented 1 year ago

upon further investigation the seems to happen something like this

get a db instance from SQLiteOpenHelper.getWritableDatabase() get a 2nd db instance from SQLiteOpenHelper.getWritableDatabase() run multiple database.rawExecSQL(query) on 2nd instance do queries, inserts, deletes on first instance

eventually the app crashes with connection pool reference count as 0.

developernotes commented 1 year ago

Hi @zkrige,

Thanks for reaching out. Are you able to reproduce the issue in a standalone application? We'd be happy to review a small public sample if you're able to.

sjlombardo commented 1 year ago

Hi @zkrige - were you able to reproduce this issue in a standalone sample?

zkrige commented 1 year ago

Apologies - I haven't gotten around to building a standalone app

zkrige commented 1 year ago

Sorry I seem to have some confusion. I reported the issue over here -https://github.com/sqlcipher/android-database-sqlcipher/issues/628#

I have since moved to using the library in this repo. I was still getting the crash in 4.5.3 of this library

We upgraded to 4.5.4 and will see how new builds behave

sjlombardo commented 9 months ago

Hello @zkrige - have you been able to reproduce this issue under 4.5.4 or 4.5.5?

zkrige commented 9 months ago

Unfortunately still seeing this fairly consistently on 4.5.4. I haven't tested 4.5.5 yet - I will implement and see how it goes

zkrige commented 8 months ago

I'm seeing the same on 4.5.5

developernotes commented 8 months ago

Hi @zkrige,

Thank you for your report. Would it be possible to prepare a standalone sample that showcases the behavior you are experiencing? This would be helpful in diagnosing the issue.

zkrige commented 8 months ago

This definitely seems to be related to doing db work on background threads

ATAL EXCEPTION: pool-33-thread-1 java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed. at net.zetetic.database.sqlcipher.SQLiteConnectionPool.throwIfClosedLocked(SQLiteConnectionPool.java:973) at net.zetetic.database.sqlcipher.SQLiteConnectionPool.waitForConnection(SQLiteConnectionPool.java:610) at net.zetetic.database.sqlcipher.SQLiteConnectionPool.acquireConnection(SQLiteConnectionPool.java:359) at net.zetetic.database.sqlcipher.SQLiteSession.acquireConnection(SQLiteSession.java:929) at net.zetetic.database.sqlcipher.SQLiteSession.executeForCursorWindow(SQLiteSession.java:869) at net.zetetic.database.sqlcipher.SQLiteQuery.fillWindow(SQLiteQuery.java:68) at net.zetetic.database.sqlcipher.SQLiteCursor.fillWindow(SQLiteCursor.java:196) at net.zetetic.database.sqlcipher.SQLiteCursor.getCount(SQLiteCursor.java:135) at android.content.ContentResolver.query(ContentResolver.java:1238) at android.content.ContentResolver.query(ContentResolver.java:1151) at android.content.ContentResolver.query(ContentResolver.java:1107) at com.itemRepo.findAllWithCounts(itemRepo.java:71)

 executorService.execute(() -> {
            final List<item> items = itemRepo.findAllWithCounts();

more specifically,

it doesnt happen every time.

it ONLY seems to happen if I have run db upgrades on app startup

private void executeInTry(SQLiteDatabase db, String query) { try { if (query.length() > 5) { db.execSQL(query); } } catch (Exception e) { Timber.w(e, "Error running SQL. [" + query + "]"); } } @Override public void onUpgrade(SQLiteDatabase db, int oldVersion, int newVersion) { for (int upgrade = oldVersion; upgrade <= newVersion; upgrade++) { if (upgrade == VER_2023_A) { db.beginTransaction(); try { db.execSQL("SOME SQL"); db.setTransactionSuccessful(); } finally { db.endTransaction(); } executeInTry(db, "CREATE INDEX xxxxxxx"); } } }

once the upgrades have been run, and the app doesnt run these statements on startup, then the reference counting seems to work.

could it be something in execsql that is releasing a reference when it shouldn't?

zkrige commented 8 months ago

not sure if this is related but im seeing a LOT of

The connection pool for database '/data/user/0/app/databases/encrypted.db' has been unable to grant a connection to thread 462 (pool-339-thread-1) with flags 0x1 for 30.594002 seconds. Connections: 0 active, 1 idle, 0 available.

for many different threads

enabling WAL seems to get rid of this, but im not sure if theres other problems that might arise

zkrige commented 8 months ago

I think this is where reference counting goes wonky. for some reason, assigning new SQLiteStatement is decreasing the db reference count

public void rawExecSQL(String sql, Object...bindArgs) throws SQLException { //mReferenceCount == 2 at this point acquireReference(); //mReferenceCount == 3 after acquiringreference try { SQLiteStatement statement = new SQLiteStatement(this, sql, bindArgs); //mReferenceCount == 2 after creating new sqlitestatement try { statement.executeRaw(); } finally { statement.close(); } } finally { //mReferenceCount == 2 releaseReference(); //mReferenceCount == 1 obviously the count is wrong here, and things go horribly wrong after this } }

But I think the reference is being released on another thread

so basically it boils down to reference counting isnt consistent across different threads

developernotes commented 7 months ago

Hi @zkrige, @theBlbDan,

Thank you for providing these details, we would like to investigate the connection pooling issue further. Can you tell us a bit more about your usage of the API so we can better understand what a recreation might entail?

When you experience the issue, are you always creating multiple SQLiteOpenHelper instances within separate threads?
- If so, how many instances do you create and how many threads are used?
Are queries run in all threads prior to this behavior presenting?
How long does it take before you are unable to acquire the connection from the pool?
Do you always experience this issue when attempting to execute a query through a ContentResolver?
Does this only occur when not in WAL mode, or does WAL mode produce this behavior as well?

zkrige commented 7 months ago

thanks for looking at this

we use a single SQLiteOpenHelper via a singleton
I'm not able to determine whether or not this is a factor
because of the inconsistency I cant pin down a time frame
all queries are done through ContentResolver so im not sure if it happens any other way
it seems to happen regardless of wether or not WAL is enabled

sorry im not able to provide more info.

In our google play pre-release testing, one device consistently fails but the other 9 devices pass without any issues

developernotes commented 7 months ago

Hi @zkrige,

all queries are done through ContentResolver so im not sure if it happens any other way

When this occurs, do you know if they are SELECT queries, mutating queries, or both that have run on that device leading up to the situation?

In our google play pre-release testing, one device consistently fails but the other 9 devices pass without any issues

Can you share what device and OS version the crash is occurring on?

zkrige commented 7 months ago

It looks like select queries throw the error, but im not sure which sql statement is prematurely closing the connection
google Pixel 7, 1080x2400,Android 13 (SDK 33), 8,192 MB, arm64-v8a

developernotes commented 7 months ago

Hi @zkrige, thank you for the update. What devices/OS versions do you not see this issue occurring on?

theBlbDan commented 7 months ago

I use the 'ol singleton approach

public class DataBaseHelper extends SQLiteOpenHelper {
    private final String DATABASE_PATH;
    private static final HashMap<String, DataBaseHelper> sInstances = new HashMap<>();
    private SQLiteDatabase db = null;

    public static synchronized DataBaseHelper getInstance(Context context, String dbName) {
        DataBaseHelper sInstance;

        if(sInstances.containsKey(dbName)) {
            sInstance = sInstances.get(dbName);
            if (sInstance == null) {
                sInstance = new DataBaseHelper(context, dbName);
                sInstances.put(dbName, sInstance);
            }
        } else {
            sInstance = new DataBaseHelper(context, dbName);
            sInstances.put(dbName, sInstance);
        }
        return sInstance;
    }

    private DataBaseHelper(Context context, String dbName) {
        super(context, dbName, null, 1);
        DATABASE_PATH = context.getFilesDir().getPath() + "/databases/v4/" + dbName + ".blb";
        openDb();
    }

    private void openDb() {
        if(db != null && db.isOpen()) { return; }
        synchronized (BibleReaderActivity.sDataLock) {
            db = SQLiteDatabase.openDatabase(DATABASE_PATH, "A Really hard password only Batman could crack.", null, SQLiteDatabase.OPEN_READWRITE, null);
        }
    }

All of my statements are executed via method calls in DataBaseHelper via accessing the associated instance which returns either a cursor or some sort of useful Java data type. Each method calls openDb() to ensure that the db is open and available for being queried, though this is likely overkill due my workflow.

I use a very simple class that uses Executors.newSingleThreadExecutor() to simulate Google's depreciated AsyncTask class. Any access to DataBaseHelper is always some part of a chore being run through this class.

Here is an example workflow and an associated stack trace of my problematic area:

private class BuildBibleWebViewByChapter extends AsyncTasks {
    BuildBibleWebViewByChapter(VersionItem bibleItem01, VersionItem bibleItem02) {
        this.bibleItem01 = bibleItem01;
        this.bibleItem02 = bibleItem02;
    }

    @Override
    public void onPreExecute() {
        -- Prep some storage variables --
    }

    @Override
    public void doInBackground() {
        .
        .
        .
         -- Fetch some Bible data from online or local DB
(945)       // Populate the tableRows data to be returned
(946)       int trl = mBibleDataWrapper.verseData[0].length;
(947)       int dataBibleID = (mBibleDataWrapper.BibleID.chapterID * 1000);
(948)       DataBaseHelper highlightsDBH = DataBaseHelper.getInstance(mContext, DataBaseHelper.HIGHLIGHTS);
(949)       DataBaseHelper pericopeDBH = DataBaseHelper.getInstance(mContext, DataBaseHelper.BLBPERICOPE);
(950)       SparseIntArray highlights = new SparseIntArray();
(951)       String[] blbPericopeData = new String[mBibleDataWrapper.BibleID.maxVerses];
(952)
(953)       Cursor highlightsDataCursor = highlightsDBH.fetchHighlightsByChapter(mBibleDataWrapper.BibleID.chapterID);
(954)       if(highlightsDataCursor.moveToFirst())
(955)           do {
(956)               highlights.put(highlightsDataCursor.getInt(highlightsDataCursor.getColumnIndexOrThrow(DataBaseHelper.KEY_BIBLEID)), highlightsDataCursor.getInt(highlightsDataCursor.getColumnIndexOrThrow(DataBaseHelper.KEY_HIGHLIGHT_ID)));
(957)           } while(highlightsDataCursor.moveToNext());
(958)       highlightsDataCursor.close();
(959)
(960)       Cursor pericopeDataCursor = pericopeDBH.pericopeByChapter(mBibleDataWrapper.BibleID.chapterID);
(961)       Arrays.fill(blbPericopeData, "");
(962)       if(pericopeDataCursor.moveToFirst())
(963)           do {
(964)               int verse = pericopeDataCursor.getInt(pericopeDataCursor.getColumnIndexOrThrow(DataBaseHelper.KEY_VERSE));
(965)               String narration = pericopeDataCursor.getString(pericopeDataCursor.getColumnIndexOrThrow(DataBaseHelper.KEY_NARRATION));
(966)               blbPericopeData[verse-1] = "<div data-translation=\""+bibleVersionShort01+"\" class=\"pericopeNot\">"+narration+"</div>";
(967)           } while(pericopeDataCursor.moveToNext());
(968)       pericopeDataCursor.close();
        .
        .
        .
    }

    @Override
    public void onPostExecute() {
        -- Send the data back to the view controller --
    }

Here is a stack trace:

java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed.
    at net.zetetic.database.sqlcipher.SQLiteConnectionPool.throwIfClosedLocked(SQLiteConnectionPool.java:973)
    at net.zetetic.database.sqlcipher.SQLiteConnectionPool.waitForConnection(SQLiteConnectionPool.java:610)
    at net.zetetic.database.sqlcipher.SQLiteConnectionPool.acquireConnection(SQLiteConnectionPool.java:359)
    at net.zetetic.database.sqlcipher.SQLiteSession.acquireConnection(SQLiteSession.java:929)
    at net.zetetic.database.sqlcipher.SQLiteSession.executeForCursorWindow(SQLiteSession.java:869)
    at net.zetetic.database.sqlcipher.SQLiteQuery.fillWindow(SQLiteQuery.java:68)
    at net.zetetic.database.sqlcipher.SQLiteCursor.fillWindow(SQLiteCursor.java:196)
    at net.zetetic.database.sqlcipher.SQLiteCursor.getCount(SQLiteCursor.java:135)
    at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:238)
    at android.database.AbstractCursor.moveToFirst(AbstractCursor.java:277)
    at org.blueletterbible.blb.BibleView$BuildBibleWebViewByChapter.doInBackground(BibleView.java:954)
    at org.blueletterbible.blb.AsyncTasks.lambda$startBackground$0$org-blueletterbible-blb-AsyncTasks(AsyncTasks.java:20)
    at org.blueletterbible.blb.AsyncTasks$$ExternalSyntheticLambda0.run(Unknown Source:2)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
    at java.lang.Thread.run(Thread.java:1012)

A similar, yet recurring trace:

java.lang.IllegalStateException: attempt to re-open an already-closed object: SQLiteDatabase: <PATH_TO_DB>
    at net.zetetic.database.sqlcipher.SQLiteClosable.acquireReference(SQLiteClosable.java:59)
    at net.zetetic.database.sqlcipher.SQLiteDatabase.queryWithFactory(SQLiteDatabase.java:1432)
    at net.zetetic.database.sqlcipher.SQLiteDatabase.query(SQLiteDatabase.java:1308)
    at net.zetetic.database.sqlcipher.SQLiteDatabase.query(SQLiteDatabase.java:1476)
    at org.blueletterbible.blb.DataBaseHelper.fetchHighlightsByChapter(DataBaseHelper.java:843)
    at org.blueletterbible.blb.BibleView$BuildBibleWebViewByChapter.doInBackground(BibleView.java:953)
    at org.blueletterbible.blb.AsyncTasks.lambda$startBackground$0$org-blueletterbible-blb-AsyncTasks(AsyncTasks.java:20)
    at org.blueletterbible.blb.AsyncTasks$$ExternalSyntheticLambda0.run(Unknown Source:2)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
    at java.lang.Thread.run(Thread.java:764)

Our main view is reading a chapter of the Bible where we pull in data a from one or two Bible DB's (depending if reading in parallel or if fetching this data from online), data from highlights, favorites, footnotes, & pericope DB's. I never close the databases intentionally, nor do I drop the instances from the singleton except in a restore from backup or in onDestroy() in the main activity. I have about 10 very small DB's that might be open at one time. By small, I mean <100k for all but the Bible DB's, of which there would at most be two at around 20MB

The user can navigate back and forth though chapters via a pair of Prev / Next arrows, so there can be quite a few fetches back to back. However, I have yet to replicate this either on any simulator or actual device.

Let me know how I can further help.

zkrige commented 7 months ago

Hi @zkrige, thank you for the update. What devices/OS versions do you not see this issue occurring on?

so now on google play, its stopped giving the error - all 10 devices work fine

but I am seeing it in testing on my side

java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed.
at net.zetetic.database.sqlcipher.SQLiteConnectionPool.throwIfClosedLocked(SQLiteConnectionPool.java:973)
at net.zetetic.database.sqlcipher.SQLiteConnectionPool.waitForConnection(SQLiteConnectionPool.java:610)
at net.zetetic.database.sqlcipher.SQLiteConnectionPool.acquireConnection(SQLiteConnectionPool.java:359)
at net.zetetic.database.sqlcipher.SQLiteSession.acquireConnection(SQLiteSession.java:929)
at net.zetetic.database.sqlcipher.SQLiteSession.executeForCursorWindow(SQLiteSession.java:869)
at net.zetetic.database.sqlcipher.SQLiteQuery.fillWindow(SQLiteQuery.java:68)
at net.zetetic.database.sqlcipher.SQLiteCursor.fillWindow(SQLiteCursor.java:196)
at net.zetetic.database.sqlcipher.SQLiteCursor.getCount(SQLiteCursor.java:135)
at android.content.ContentResolver.query(ContentResolver.java:1248)
at android.content.ContentResolver.query(ContentResolver.java:1161)
at android.content.ContentResolver.query(ContentResolver.java:1117)
at app.someRepository.findAllWithCounts(repository.java:74)

this specific query happens on an executor service background thread

developernotes commented 7 months ago

Hi @zkrige, @theBlbDan,

I haven't been able to reproduce the behavior you are seeing with the connection pool closing. I put together an admittedly small application to generate data load via an ExecutorService coordinating reading data from many threads and writing data from another thread (the majority of the coordination occurs here^1). When you get an opportunity, would you take a look at this ^2 project to see if you experience the connection pool issue on any of your devices, or if there is a usage scenario that is different that might also reproduce it? Thanks!

zkrige commented 7 months ago

I removed the executor service and I still get the crash on main thread. In my case it was happening from a content resolver but in @theBlbDan case it seems to be happening directly on cursor queries

How important is it to reference count the resources? Is there not some other way to handle auto closing?

developernotes commented 7 months ago

Hi @zkrige,

The reference counting behavior originates from the upstream android.database.sqlite ^1 implementation, we'd prefer not to deviate from that. Are you only seeing the crash on a Pixel 7 device?

zkrige commented 7 months ago

Ah I understand

I'm seeing it on emulator as well now.

zkrige commented 7 months ago

Device(s) with issues Google Pixel 7 (panther) - Android 13 Google Pixel 5 (redfin) - Android 11 Motorola Motorola G20 (java) - Android 11 Samsung Galaxy S20 (x1q) - Android 10 Google Pixel 5 64-bit only (Beta) (redfin_beta_64) - Android 14

Exceptions java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed. java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed. java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed. java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed. java.lang.IllegalStateException: Cannot perform this operation because the connection pool has been closed.

developernotes commented 7 months ago

Hi @zkrige,

Did you experience these exceptions with your application, or the sample application posted here?

zkrige commented 5 months ago

I experience these crashes with our application - not the sample app. I believe the sample app isnt complicated enough to get the reference counting to break

zkrige commented 1 month ago

just bumping this


  at net.zetetic.database.sqlcipher.SQLiteConnectionPool.throwIfClosedLocked (SQLiteConnectionPool.java:974)
  at net.zetetic.database.sqlcipher.SQLiteConnectionPool.waitForConnection (SQLiteConnectionPool.java:611)
  at net.zetetic.database.sqlcipher.SQLiteConnectionPool.acquireConnection (SQLiteConnectionPool.java:360)
  at net.zetetic.database.sqlcipher.SQLiteSession.acquireConnection (SQLiteSession.java:929)
  at net.zetetic.database.sqlcipher.SQLiteSession.executeForCursorWindow (SQLiteSession.java:869)
  at net.zetetic.database.sqlcipher.SQLiteQuery.fillWindow (SQLiteQuery.java:68)
  at net.zetetic.database.sqlcipher.SQLiteCursor.fillWindow (SQLiteCursor.java:196)
  at net.zetetic.database.sqlcipher.SQLiteCursor.getCount (SQLiteCursor.java:135)
  at android.content.ContentResolver.query (ContentResolver.java:1248)
  at android.content.ContentResolver.query (ContentResolver.java:1161)
  at android.content.ContentResolver.query (ContentResolver.java:1117)
  at za.co.snapplify.repository.CategoryRepo.findAllWithCounts (CategoryRepo.java:74)
  at za.co.snapplify.ui.browse.BrowseActivity$CategoryContentObserver.loadCategories (BrowseActivity.java:591)
  at za.co.snapplify.ui.browse.BrowseActivity$CategoryContentObserver.onChange (BrowseActivity.java:586)
  at android.database.ContentObserver.onChange (ContentObserver.java:170)
  at android.database.ContentObserver.onChange (ContentObserver.java:188)
  at android.database.ContentObserver.onChange (ContentObserver.java:224)
  at android.database.ContentObserver.lambda$dispatchChange$0 (ContentObserver.java:304)
  at android.database.ContentObserver.$r8$lambda$ZTAX5Dz0QB2gJk_nBFGhENlKHoI
  at android.database.ContentObserver$$ExternalSyntheticLambda0.run
  at android.os.Handler.handleCallback (Handler.java:958)
  at android.os.Handler.dispatchMessage (Handler.java:99)
  at android.os.Looper.loopOnce (Looper.java:230)
  at android.os.Looper.loop (Looper.java:319)
  at android.app.ActivityThread.main (ActivityThread.java:8893)
  at java.lang.reflect.Method.invoke
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:608)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1103)```

developernotes commented 1 month ago

Hi @zkrige,

I'm sorry, we have not been able to reproduce the behavior you are seeing, even with a sample application. If you get the time to isolate the issue further into a reproduction case, we would be happy to dig into the issue further.

sqlcipher / sqlcipher-android

Connection pool closing causing app crash #15