Weird DB Error after upgrade

[bleuf1shi]

I'm not sure what happened but I figure I'd report any weirdness.

The application got stuck in an infinite error loop :-1:

Here's a small snippet from my DatabaseMaster class:

    @Override
    protected void onConfigure(SQLiteDatabaseWrapper db) {
        db.enableWriteAheadLogging();
    }

    @Override
    protected void onOpen(SQLiteDatabaseWrapper db) {
        super.onOpen(db);
        mIsDbReady = true;
        LogUtils.log(TAG, "DB is ready!", null, Log.VERBOSE);
    }

07-21 16:30:07.773 4876-4876/org.fire.line V/~F~MyApplication: onCreate() 07-21 16:30:07.823 4876-4904/org.fire.line V/~F~TimeSyncIntentService: runTimeSyncServiceNow() 07-21 16:30:08.158 4876-4904/org.fire.line V/~F~DatabaseMaster: DB is ready! 07-21 16:30:08.169 4876-4904/org.fire.line E/SQLiteLog: (5) statement aborts at 2: [PRAGMA journal_mode=PERSIST] 07-21 16:30:08.209 4876-4876/org.fire.line V/~F~ActivityMain: onResume() 07-21 16:30:08.214 4876-4904/org.fire.line W/SQLiteConnection: Could not change the database journal mode of '/data/user/0/org.fire.line/databases/org.fire.line_db_master.db' from 'wal' to 'PERSIST' because the database is locked. This usually means that there are other open connections to the database which prevents the database from enabling or disabling write-ahead logging mode. Proceeding without changing the journal mode. 07-21 16:30:08.242 4876-4904/org.fire.line V/~F~DatabaseMaster: DB is ready! 07-21 16:30:08.259 4876-4904/org.fire.line E/SQLiteLog: (5) statement aborts at 2: [PRAGMA journal_mode=PERSIST] 07-21 16:30:08.262 4876-4904/org.fire.line W/SQLiteConnection: Could not change the database journal mode of '/data/user/0/org.fire.line/databases/org.fire.line_db_master.db' from 'wal' to 'PERSIST' because the database is locked. This usually means that there are other open connections to the database which prevents the database from enabling or disabling write-ahead logging mode. Proceeding without changing the journal mode.

[sbosley]

Hmm, never seen anything like that before. Can you post what version of Android this was on and what version of SquiDB you're using? And can you confirm that your DatabaseMaster instance is an app-wide singleton?

[sbosley]

Also, on the off chance it's related, are you doing anything with attached databases?

[bleuf1shi]

MotoG 2nd Generation, Android Marshmellow, com.yahoo.squidb:squidb:2.0.0

It happened during development. Confirm, it is an app-wide singleton.

That was the first and only time it's happened. I moved around some of the new code I was testing and it hasn't happened.

weird.

[sbosley]

Very weird. We did change some of the logic around opening databases to be more robust in the face of obscure problems opening the database in version 2.0.3 using some new hooks, so you could upgrade to that version or later to try those things out.

Also, I found this in the comments of the android source code; might be relevant:

// Because we always disable WAL mode when a database is first opened // (even if we intend to re-enable it), we can encounter problems if // there is another open connection to the database somewhere. // This can happen for a variety of reasons such as an application opening // the same database in multiple processes at the same time or if there is a // crashing content provider service that the ActivityManager has // removed from its registry but whose process hasn't quite died yet // by the time it is restarted in a new process.

That was the main reason I had asked about the singleton thing, but maybe there was just a stray open connection from a previous process somewhere?

Edit: I just noticed that this comment in the android source code in fact appears right above the log statement that you posted: "This usually means that there are other open connections to the database..." etc. So I think that lends credence to the guess is that there was a stray process that hadn't finished cleaning up its connections or somehow a non-singleton SquidDatabase snuck in there (probably the former if you've confirmed things are singletons).

[bleuf1shi]

This did happen immediately after building a new dev build on top of another dev build? maybe the uninstall didn't finish completely?

[sbosley]

It's certainly possible. Was it an actual infinite loop that you saw or did it just log that statement a few times and then eventually stop?

[bleuf1shi]

I believe infinite, it went on for a solid 5min.

[sbosley]

A few other things that might help us track down possible causes:

• Do any components of your app that might access the database run in separate processes?
• Do you override/implement any other hooks, like onTablesCreated() or onMigrationFailed()? If so, do these hooks do anything of interest?
• Do you at any point call the recreate() method? (This method was not particularly safe prior to version 2.0.3).

Also, the new onDatabaseOpenFailed() hook introduced in version 2.0.3 can help you debug such problems by logging stack traces and/or short-circuiting during the database opening process if for any reason something goes wrong either opening the DB file or with the recovery logic after a failed migration. However, the logs you posted suggest that the file was locked by some other process, which is probably still the most likely cause of weird behavior. Maybe like you suggested the uninstall didn't finish completely, or maybe something like Instant Run was behaving badly if that was turned on.