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

Status: RESOLVED WONTFIX

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

Description

[Scoobidiver (away)]

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

Comment 1

[Scoobidiver (away)]

It was hit by a new user in 18.0a1/20120922.

Comment 2

[Scoobidiver (away)]

It's #18 top crasher in 18.0a2 and #6 in 19.0a1.

Comment 3

[Scoobidiver (away)]

It stopped after 18.0a2/20121105 and 19.0a1/20121116.

Comment 4

[Scoobidiver (away)]

It's #1 top crasher in 19.0b1.

Crashes are now exclusively on JB.

Comment 5

[Alex Keybl [:akeybl]]

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.

Comment 6

[Brad Lassey [:blassey] (use needinfo?)]

Lucas, given that the crashes are JB only, I wonder if this is due to its multi-user support.

Comment 7

[Kevin Brosnan [Ex-Mozilla]]

Not trivially related. Each user has their own data store. Though there may be some things to test around updating.

Comment 8

[Scoobidiver (away)]

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.

Comment 10

[Lucas Rocha (:lucasr)]

(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).

Comment 11

[Aaron Train [:aaronmt]]

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.

Comment 12

[Alex Keybl [:akeybl]]

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.

Comment 13

[Scoobidiver (away)]

It's again #1 top crasher in the first hours of 19.0.

Comment 14

[Brad Lassey [:blassey] (use needinfo?)]

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

Comment 15

[Brad Lassey [:blassey] (use needinfo?)]

(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?

Comment 16

[Alex Keybl [:akeybl]]

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.

Comment 17

[Robert Kaiser]

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)

Comment 18

[Aaron Train [:aaronmt]]

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

Comment 19

[Richard Newman [:rnewman]]

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.

Comment 20

[Mark Finkle (:mfinkle) (use needinfo?)]

(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.

Comment 21

[Richard Newman [:rnewman]]

(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.

Comment 22

[Alex Keybl [:akeybl]]

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.

Comment 23

[Kevin Brosnan [Ex-Mozilla]]

I'll take a look at this and see if the logging has anything useful.

Comment 24

[Scoobidiver (away)]

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

Comment 25

[Alex Keybl [:akeybl]]

(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.

Comment 26

[Kevin Brosnan [Ex-Mozilla]]

Attachment: Sanatized json from the crash report (logcat + java stack)

Comment 27

[Lucas Rocha (:lucasr)]

Not actively working on this.

Comment 28

[Brad Lassey [:blassey] (use needinfo?)]

filter on [mass-p5]

Comment 29

[BugBot [:suhaib / :marco/ :calixte]]

Closing because no crashes reported for 12 weeks.

Comment 30

[BugBot [:suhaib / :marco/ :calixte]]

Closing because no crashes reported for 12 weeks.

Comment 31

[Chris Peterson [:cpeterson]]

Removing steps-wanted keyword because this bug has been resolved.

Comment 32

[Chris Peterson [:cpeterson]]

Removing steps-wanted keyword because this bug has been resolved.