Closed Bug 791958 Opened 7 years ago Closed Last year

android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method) on JB

Categories

(Firefox for Android :: Data Providers, defect, P5, critical)

ARM
Android
defect

Tracking

()

RESOLVED WONTFIX
Tracking Status
firefox16 --- affected
firefox17 --- affected
firefox18 --- affected
firefox19 + affected
firefox20 + wontfix
fennec + ---

People

(Reporter: scoobidiver, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: crash, steps-wanted, Whiteboard: [native-crash][startupcrash])

Crash Data

Attachments

(1 file)

There are two crashes from the same user in 18.0a1/20120917, including bp-799df40c-e6e8-45cc-8b21-e49cd2120917.

android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode
	at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method)
	at android.database.sqlite.SQLiteConnection.acquirePreparedStatement(SQLiteConnection.java:882)
	at android.database.sqlite.SQLiteConnection.executeForString(SQLiteConnection.java:627)
	at android.database.sqlite.SQLiteConnection.setJournalMode(SQLiteConnection.java:313)
	at android.database.sqlite.SQLiteConnection.setWalModeFromConfiguration(SQLiteConnection.java:287)
	at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:215)
	at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:193)
	at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)
	at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)
	at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)
	at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:804)
	at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:789)
	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:694)
	at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:836)
	at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:221)
	at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:224)
	at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:164)
	at org.mozilla.gecko.db.DBUtils.ensureDatabaseIsNotLocked(DBUtils.java:76)
	at org.mozilla.fennec.db.BrowserProvider.getDatabaseHelperForProfile(BrowserProvider.java:1210)
	at org.mozilla.fennec.db.BrowserProvider.getReadableDatabase(BrowserProvider.java:1249)
	at org.mozilla.fennec.db.BrowserProvider.query(BrowserProvider.java:1744)
	at android.content.ContentProvider.query(ContentProvider.java:652)
	at android.content.ContentProvider$Transport.query(ContentProvider.java:189)
	at android.content.ContentResolver.query(ContentResolver.java:370)
	at android.content.ContentResolver.query(ContentResolver.java:313)
	at org.mozilla.gecko.db.LocalBrowserDB.filterAllSites(LocalBrowserDB.java:166)
	at org.mozilla.gecko.db.LocalBrowserDB.getTopSites(LocalBrowserDB.java:190)
	at org.mozilla.gecko.db.BrowserDB.getTopSites(BrowserDB.java:101)
	at org.mozilla.gecko.AboutHomeContent.loadTopSites(AboutHomeContent.java:257)
	at org.mozilla.gecko.AboutHomeContent.access$400(AboutHomeContent.java:59)
	at org.mozilla.gecko.AboutHomeContent$9.run(AboutHomeContent.java:288)
	at android.os.Handler.handleCallback(Handler.java:615)
	at android.os.Handler.dispatchMessage(Handler.java:92)
	at android.os.Looper.loop(Looper.java:137)
	at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)

More reports at:
https://crash-stats.mozilla.com/report/list?signature=android.database.sqlite.SQLiteDatabaseLockedException%3A+database+is+locked+%28code+5%29%3A+%2C+while+compiling%3A+PRAGMA+journal_mode+at+android.database.sqlite.SQLiteConnection.nativePrepareStatement%28Native+Method%29
It was hit by a new user in 18.0a1/20120922.
It's #18 top crasher in 18.0a2 and #6 in 19.0a1.
tracking-fennec: --- → ?
Keywords: topcrash
tracking-fennec: ? → +
Summary: android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method) → android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method) on ICS and above
It stopped after 18.0a2/20121105 and 19.0a1/20121116.
Keywords: topcrash
It's #1 top crasher in 19.0b1.

Crashes are now exclusively on JB.
tracking-fennec: + → ?
Keywords: topcrash
Summary: android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method) on ICS and above → android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method) on JB
Component: General → Data Providers
Brad - can you help us find an assignee for this top crasher? If we find a low risk backout/fix, we may consider inclusion in an 18.0.1.
Assignee: nobody → blassey.bugs
Lucas, given that the crashes are JB only, I wonder if this is due to its multi-user support.
Assignee: blassey.bugs → lucasr.at.mozilla
Not trivially related. Each user has their own data store. Though there may be some things to test around updating.
tracking-fennec: ? → 19+
There are less crashes in 19.0b2 (#12 top crasher) now that the transition between 18.0 Beta and 19.0 Beta is done. It will likely be a top crasher again with the upgrade from 18.0 Release to 19.0 Release.
Duplicate of this bug: 821637
(In reply to Brad Lassey [:blassey] from comment #6)
> Lucas, given that the crashes are JB only, I wonder if this is due to its
> multi-user support.

Very unlikely. This crash seems to happen on the very first query sent to the content provider on Fennec's startup (about:home bits). This is likely a result of Fennec not being closed cleanly. The previous instance of this bug happen on mostly after apk updates.

Someone needs to find a way to reproduce this bug after an app upgrade and tell me if there are any fennec zombie processes around (adb shell ps aux).
Using the Galaxy Note II (Android 4.2), and my Nexus S (Android 4.1), tried loading up a large profile, enabling Sync, having a bunch of tabs open, add-ons installed/pending install, the whole deal and tried upgrading 17 to 18, and then doing an initial search and could not reproduce. Even forced a broadcast of the low memory intent just prior to install and that did nothing.

Also tried user-support as indicated above on my Nexus 7;

In all cases, no fennec zombie processes were visible.

No other leads on this one.
No longer a top crash, so untracking (likely permanently). My suggestion to QA would be to:

1) Install a FF18 beta APK from FTP
2) Disable WiFi
3) Enable automatic updating of Firefox Beta on WiFi in the Play Store
4) Launch Firefox Beta
5) Enable WiFi, which usually kicks off an automatic update
6) Continue using Firefox Beta while the updates occur

and another variant would be where we weren't using Firefox during the update.

We'd take a low risk uplift (but not for FF19 at this point) once the investigation has completed.
Keywords: topcrash
Crash Signature: [@ android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): , while compiling: PRAGMA journal_mode at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method)] → [@ android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5): while compiling: PRAGMA journal_mode at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method)] [@ android.database.sqlite.SQLiteDatabaseLocke…
It's again #1 top crasher in the first hours of 19.0.
Keywords: topcrash
comments around the throwing code:
74             // This call should not throw if the forced unlocking
75             // actually fixed the situation.
76             dbHelper.getWritableDatabase();
77 
78             // TODO: maybe check if the database is still locked and let the
79             // user know that the device needs rebooting?

so, maybe it is time to do this TODO
(In reply to Brad Lassey [:blassey] from comment #14)
> comments around the throwing code:
> 74             // This call should not throw if the forced unlocking
> 75             // actually fixed the situation.
> 76             dbHelper.getWritableDatabase();
> 77 
> 78             // TODO: maybe check if the database is still locked and let
> the
> 79             // user know that the device needs rebooting?
> 
> so, maybe it is time to do this TODO

Also, if we throw here, we're up a creek and should just log everything. Dump the active processes (maybe filtered to Mozilla ones) and a list of threads. Is there anything else that might be useful, I noticed in bug 752828 mfinkle was asking a user to run "adb shell setprop log.tag.GeckoBrowserProvider DEBUG" to get more useful logging. Can we log that detailed info just before we know we'll be crashing?
We're going to be taking bug 843029 (and another bug for extra logging) for FF20b1 to catch the FF19->FF20b1 update, where we expect to see this issue again.
Depends on: 843029
No longer depends on: 843029
So, it looks like people are running into this repeatedly, which also makes it different from bug 752828:

breakpad=> SELECT version,COUNT(*) as crashes,COUNT(DISTINCT client_crash_date - install_age  * interval '1 second') as installations FROM reports WHERE product='FennecAndroid' AND signature LIKE '%database is locked (code 5)%' AND utc_day_is(date_processed, '2013-02-20') GROUP BY version;
 version | crashes | installations 
---------+---------+---------------
 19.0    |    2844 |           649
 20.0a2  |       2 |             1
(2 rows)
Depends on: 843029
Just listing some areas I've tried to trigger this the past few days; still unable to reproduce

Device: Samsung Galaxy Note 2 (samsung/t03gxx/t03g:4.1 in the reports)

* 17 (Sync, import bookmarks/history, 25 loaded tabs open) -> upgrade to -> 18 (ADB), restore 25 loaded tabs -> upgrade to 19 (via Play Store) while running
* 18 (25 loaded tabs -> import bookmarks/history) -> upgrade to 19 (via Play Store) while running

Device: Samsung Galaxy Note (samsung p4notewifixx/p4n:4.1 in the reports)

* 18.0.2 (triggered a Sync, added 150 bookmarks, 10 open tabs) -> trigger a Sync -> upgrade to 19 (via Play Store) while running
This particular error also seems to be thrown in certain concurrent access scenarios: you can't have more than one transaction or more than one thread accessing the DB. And on first run we have about:home trying to load, DB migration wanting to run, and perhaps also the content provider being accessed by Sync.

(And I've also seen mention of this being due to timeouts, or the use of multiple SqliteHelpers.)

The first time we saw this kind of problem it was due to unclean shutdown, but I would speculate that the current issue is a concurrency problem.
(In reply to Richard Newman [:rnewman] from comment #19)
> This particular error also seems to be thrown in certain concurrent access
> scenarios: you can't have more than one transaction or more than one thread
> accessing the DB. And on first run we have about:home trying to load, DB
> migration wanting to run, and perhaps also the content provider being
> accessed by Sync.
> 
> (And I've also seen mention of this being due to timeouts, or the use of
> multiple SqliteHelpers.)
> 
> The first time we saw this kind of problem it was due to unclean shutdown,
> but I would speculate that the current issue is a concurrency problem.

I agree about the concurrency possibility. We added code to look for locked files from poor shutdowns, so we'll find out if that possibility still exists too.

We have been going through the Application code looking for any places where DB access is not happening on GeckoBackgroundThread and changing the code if needed. We are moving to use UiAsyncTask whenever possible because it allows us to specify the thread used for the background task, while AsyncTask does not.

I had thought the DB upgrade code (in onUpgrade) runs on the same thread as the DB request that kicks it off, but I am not 100% sure.

How Sync interacts in this equation is the part I am most ignorant about. Since Sync uses the content providers, we at least use the same code paths, but what thread is the DB work using? We should only be using a single SqliteHelper for each provider, which rules out that possibility.
(In reply to Mark Finkle (:mfinkle) from comment #20)

> How Sync interacts in this equation is the part I am most ignorant about.
> Since Sync uses the content providers, we at least use the same code paths,
> but what thread is the DB work using? We should only be using a single
> SqliteHelper for each provider, which rules out that possibility.

It will be using a collection of non-Gecko threads.

This is why the Android docs advise that your content providers all be thread-safe, because they won't do it for you.

Ordinarily, access to SQLite is serialized by the helper, so most systems don't need to explicitly synchronize their CPs; they're thread-safe by accident.

That probably ceases to be true if they explicitly begin and end transactions without careful synchronization.

If it's possible to end up with two different DB handles (perhaps by touching the CP from a different ContentResolver in a different Context and thread, as Sync does?), or begin a transaction before Gecko manages to (e.g., because Android starts a sync when you launch the app, and it's implicitly opened a transaction while Gecko attempts to write into history?), then concurrency problems might result.
To keep everybody in the loop, we're taking bug 843029 and bug 843361 into FF20b1 to watch for similar issues when updating from FF19bX->FF20b1. Based upon the success of those bugs and the trend of this crash over a few days (today's data isn't in yet) we may choose to spin a mobile 19.0.1 or resolve for the first time in FF20.
I'll take a look at this and see if the logging has anything useful.
QA Contact: kbrosnan
With combined signatures, it's #16 top crasher in 19.0.2, so not enough to qualify it for the topcrash keyword according to https://wiki.mozilla.org/CrashKill/Topcrash
Keywords: topcrash
(In reply to Kevin Brosnan [:kbrosnan] from comment #23)
> I'll take a look at this and see if the logging has anything useful.

Any word?

Are we looking for logs from affected users? That may be difficult, since we've never made contact with an impacted user.
Flags: needinfo?(kbrosnan)
tracking-fennec: 19+ → 21+
tracking-fennec: 21+ → +
Keywords: qawanted
Not actively working on this.
Assignee: lucasr.at.mozilla → nobody
Blocks: 975024
filter on [mass-p5]
Priority: -- → P5
Crash Signature: android.database.sqlite.SQLiteConnection.nativeExecute(Native Method)] → android.database.sqlite.SQLiteConnection.nativeExecute(Native Method)] [@ android.database.sqlite.SQLiteDatabaseLockedException: database is locked : , while compiling: PRAGMA journal_mode at android.database.sqlite.SQLiteConnection.nativePrepareStateme…
Closing because no crashes reported for 12 weeks.
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → WONTFIX
Closing because no crashes reported for 12 weeks.
You need to log in before you can comment on or make changes to this bug.