750950 - Crash shortly after startup, about:home not filled in

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Martijn Wargers (dead)]

Attachment: logcat

On the Samsung galaxy Nexus, I'm currently crashing with current Native trunk build, shortly after startup.
About:home is not filled in and soon after, Fennec crashes.

I got in this state after a previous crash, if I remember correctly.

I guess this is the relevant part of logcat:
05-02 01:02:18.317 E/SQLiteDatabase(30052): close() was never explicitly called on database '/data/data/org.mozilla.fennec/files/mozilla/wzho9h6h.default/browser.db' 
05-02 01:02:18.317 E/SQLiteDatabase(30052): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteDatabase.<init>(SQLiteDatabase.java:1943)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:1007)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:986)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:1051)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:770)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:221)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:157)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.db.DBUtils.ensureDatabaseIsNotLocked(DBUtils.java:76)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.fennec.db.BrowserProvider.getDatabaseHelperForProfile(BrowserProvider.java:977)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.fennec.db.BrowserProvider.getReadableDatabase(BrowserProvider.java:1016)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.fennec.db.BrowserProvider.query(BrowserProvider.java:1538)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.content.ContentProvider$Transport.query(ContentProvider.java:178)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.content.ContentResolver.query(ContentResolver.java:311)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.db.LocalBrowserDB.filterAllSites(LocalBrowserDB.java:173)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.db.LocalBrowserDB.getTopSites(LocalBrowserDB.java:195)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.db.BrowserDB.getTopSites(BrowserDB.java:119)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.AboutHomeContent.loadTopSites(AboutHomeContent.java:346)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.AboutHomeContent.access$400(AboutHomeContent.java:95)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.AboutHomeContent$9.run(AboutHomeContent.java:375)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.os.Handler.handleCallback(Handler.java:605)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.os.Handler.dispatchMessage(Handler.java:92)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at android.os.Looper.loop(Looper.java:137)
05-02 01:02:18.317 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
05-02 01:02:18.325 E/SQLiteDatabase(30052): close() was never explicitly called on database '/data/data/org.mozilla.fennec/files/mozilla/wzho9h6h.default/browser.db' 
05-02 01:02:18.325 E/SQLiteDatabase(30052): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteDatabase.<init>(SQLiteDatabase.java:1943)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:1007)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:986)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:1051)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:770)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:221)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:157)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.db.DBUtils.ensureDatabaseIsNotLocked(DBUtils.java:85)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.fennec.db.BrowserProvider.getDatabaseHelperForProfile(BrowserProvider.java:977)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.fennec.db.BrowserProvider.getReadableDatabase(BrowserProvider.java:1016)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.fennec.db.BrowserProvider.query(BrowserProvider.java:1538)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.content.ContentProvider$Transport.query(ContentProvider.java:178)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.content.ContentResolver.query(ContentResolver.java:311)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.db.LocalBrowserDB.filterAllSites(LocalBrowserDB.java:173)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.db.LocalBrowserDB.getTopSites(LocalBrowserDB.java:195)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.db.BrowserDB.getTopSites(BrowserDB.java:119)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.AboutHomeContent.loadTopSites(AboutHomeContent.java:346)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.AboutHomeContent.access$400(AboutHomeContent.java:95)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.AboutHomeContent$9.run(AboutHomeContent.java:375)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.os.Handler.handleCallback(Handler.java:605)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.os.Handler.dispatchMessage(Handler.java:92)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at android.os.Looper.loop(Looper.java:137)
05-02 01:02:18.325 E/SQLiteDatabase(30052): 	at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)

Comment 1

[Martijn Wargers (dead)]

A reboot of the phone seems to have fixed it.
So I guess it's some kind of database locking issue or something?

Comment 2

[Martijn Wargers (dead)]

Ok, I'm in this state again, after some hang/crash from Fennec.

(I got into this hang/crash state after visiting this page: http://www.telegraaf.nl/binnenland/12040352/__Juwelierkillers_gevlucht_naar_Belgi__.html and playing the Flash video there).

Comment 3

[Lucas Rocha (:lucasr)]

Ok, logcat shows that my patch is not fixing the locking issue, at least for this device. We'll have to investigate this issue a bit more.

Comment 5

[Lucas Rocha (:lucasr)]

Martijn, could you please run "adb shell ps" and post the output here when the DB locking happens again?

Comment 6

[Martijn Wargers (dead)]

Attachment: adb shell ps when this happens

Ok, I'm currently again in this state, after Fennec hung (this is with a testcase, I'm still working on, although it should crash, not han).

Comment 7

[Martijn Wargers (dead)]

Attachment: adb shell ps after Fennec crashed

This is 'adb shell ps' after Fennec has closed because of this bug.
I see it still in the list of processes.

Comment 8

[Lucas Rocha (:lucasr)]

Ok, my suspicion was correct (this is why I asked for the list of processes). What is actually happening is that there's a zombie Fennec process holding the database lock. Need to figure out a way to ensure that we cleanly exit all Fennec processes before re-starting the app after an update or crash.

Comment 9

[Lucas Rocha (:lucasr)]

I created a build that kills any zombie processes when the providers are created. My current theory is that zombie processes are holding the mysterious database lock when we crash. Here's the apk:

http://dl.dropbox.com/u/1187037/kill-zombies-fennec.apk

Martijn, could you please try to reproduce the bug using this build?

Comment 10

[Martijn Wargers (dead)]

Unfortunately, Fennec isn't in this state, currently on my device and I'm not sure how to get into this state.

Comment 11

[Martijn Wargers (dead)]

I've tried it now quite some time to get into this state, but I'm unable to :/

Comment 12

[Lucas Rocha (:lucasr)]

Attachment: Kill any zombie processes if database is locked

Comment 13

[Lucas Rocha (:lucasr)]

This APK has this patch applied. It will log a message with a "GeckoDBUtils" prefix when the locking issue happens and we try to auto-fix it:

  http://dl.dropbox.com/u/1187037/kill-zombies-fennec.apk

It would be nice if QA could try very hard to reproduce the locking issue using this APK. If you see GeckoDBUtils in logcat and Fennec continues to work fine, this means that the patch actually fixes the problem.

Comment 14

[Lucas Rocha (:lucasr)]

Pushed: http://hg.mozilla.org/integration/mozilla-inbound/rev/b7fb17a9702f

Comment 15

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/mozilla-central/rev/b7fb17a9702f

Comment 16

[Martijn Wargers (dead)]

I had a build before this fix that had this crash on startup.
I then installed a build from http://nightly.mozilla.org , from after this fix went in.
For some reason, it still closed shortly after startup the first time, but when I started up the second time, it worked fine (although I didn't see 'Your tabs from last time').

That's the closest I can get to verifying this bug.

I had sort of a way of reproducing this, but it involved complicated steps that I had to take and most of the times I would just crash. When I try to reproduce it that way now, I always seem to crash directly.

Comment 17

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

Lucas - Can you a? and provide a risk assessment for uplifting to aurora

Comment 18

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

https://hg.mozilla.org/releases/mozilla-aurora/rev/7ced703e9e52

Comment 20

[Martijn Wargers (dead)]

Ok, now I'm pretty certain this is fixed.
I again got into this situation.
So with this patch, I get a crash shortly after startup the first time, then upon a restart, Fennec is working again and I don't have any tabs from last time.