746444 - Java UI up and running requests to load pages via the home screen or awesome bar fail to load

Status: RESOLVED FIXED

Description

[Kevin Brosnan [:kbrosnan]]

Attachment: Full logcat dumped from the phone

Damon said that he was trying to use Flash and then Firefox crashed. Upon restarting the Java UI was up and responsive however clicking on a home tab, Sync'ed tab or a awesome screen item did not browse to the page. I grabbed a logcat from his phone. I believe the relevant parts are the following. Specifically after "04-17 17:38:42.565 E/GeckoApp(11637): error building JSON arguments" there are several requests for tabs that correspond to when the problem was happening.

This was using a Galaxy Nexus

04-17 17:38:34.260 I/ActivityManager(  200): START {act=android.intent.action.MAIN flg=0x10200000 cmp=org.mozilla.fennec/.App} from pid 1618
04-17 17:38:34.330 I/GeckoApp(11637): configuration changed
04-17 17:38:34.385 W/GeckoApp(11637): zerdatime 4123717 - onNewIntent
04-17 17:38:34.385 I/GeckoApp(11637): Intent : ACTION_MAIN
04-17 17:38:34.385 I/GeckoApp(11637): restart
04-17 17:38:34.385 W/GeckoApp(11637): zerdatime 4123718 - onStart
04-17 17:38:34.385 I/GeckoApp(11637): start
04-17 17:38:34.385 I/GeckoApp(11637): resume
04-17 17:38:34.385 I/GeckoApp(11637): application resumed
04-17 17:38:34.393 I/WindowManager(  200): createSurface Window{41dbd120 SurfaceView paused=false}: DRAW NOW PENDING
04-17 17:38:34.447 D/dalvikvm(11637): GC_CONCURRENT freed 537K, 20% free 16816K/20935K, paused 3ms+7ms
04-17 17:38:34.479 I/WindowManager(  200): createSurface Window{41d91148 org.mozilla.fennec/org.mozilla.fennec.App paused=false}: DRAW NOW PENDING
04-17 17:38:34.588 D/dalvikvm(11637): GC_CONCURRENT freed 896K, 20% free 16852K/20935K, paused 5ms+4ms
04-17 17:38:34.736 W/ResourceType(  200): Skipping entry 0x7f050000 in package table 0 because it is not complex!
04-17 17:38:34.736 W/ResourceType(  200): Skipping entry 0x7f050001 in package table 0 because it is not complex!
04-17 17:38:34.736 D/OpenGLRenderer( 1618): Flushing caches (mode 0)
04-17 17:38:34.752 W/IInputConnectionWrapper( 1618): showStatusIcon on inactive InputConnection
04-17 17:38:34.752 D/OpenGLRenderer( 1618): Flushing caches (mode 1)
04-17 17:38:34.752 W/InputManagerService(  200): Starting input on non-focused client com.android.internal.view.IInputMethodClient$Stub$Proxy@41d21eb8 (uid=10023 pid=1618)
04-17 17:38:42.565 E/GeckoApp(11637): error building JSON arguments
04-17 17:38:42.565 I/GeckoApp(11637): Sending message to Gecko: 4131893 - Tab:Add
04-17 17:38:42.635 D/dalvikvm(  200): GC_EXPLICIT freed 597K, 24% free 20161K/26247K, paused 4ms+5ms
04-17 17:38:46.650 D/GeckoAboutHome(11637): Sending message to Gecko: 4135978 - Tab:Add
04-17 17:38:47.510 D/GeckoAboutHome(11637): Sending message to Gecko: 4136840 - Tab:Add
04-17 17:38:48.041 D/GeckoAboutHome(11637): Sending message to Gecko: 4137371 - Tab:Add
04-17 17:38:48.385 D/GeckoAboutHome(11637): Sending message to Gecko: 4137713 - Tab:Add
04-17 17:38:48.611 D/GeckoAboutHome(11637): Sending message to Gecko: 4137939 - Tab:Add
04-17 17:38:48.830 D/GeckoAboutHome(11637): Sending message to Gecko: 4138159 - Tab:Add
04-17 17:38:49.018 D/GeckoAboutHome(11637): Sending message to Gecko: 4138343 - Tab:Add
04-17 17:38:49.205 D/GeckoAboutHome(11637): Sending message to Gecko: 4138536 - Tab:Add
04-17 17:38:50.815 I/GeckoAboutHome(11637): clicked: http://damon.sicore.com/
04-17 17:38:50.815 I/GeckoToolbar(11637): zerdatime 4140145 - Throbber start
04-17 17:38:50.815 D/GeckoApp(11637): EDIT
04-17 17:38:54.033 I/GeckoAboutHome(11637): clicked: http://news.google.com/
04-17 17:38:54.033 I/GeckoToolbar(11637): zerdatime 4143361 - Throbber start
04-17 17:38:54.033 D/GeckoApp(11637): EDIT
04-17 17:39:01.580 D/dalvikvm(  276): GC_CONCURRENT freed 716K, 41% free 16167K/27207K, paused 3ms+5ms

Comment 1

[Erin Lancaster [:elan]]

Attachment: Another full log

Comment 2

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

More relevant log snippet:

04-17 17:30:08.523 I/WindowManager(  200): createSurface Window{41ca0a98 org.mozilla.fennec/org.mozilla.fennec.App paused=false}: DRAW NOW PENDING
04-17 17:30:08.539 I/SqliteDatabaseCpp(11552): sqlite returned: error code = 5, msg = statement aborts at 1: [PRAGMA journal_mode=TRUNCATE] , db=/data/data/org.mozilla.fennec/files/mozilla/utj4ealf.default/browser.db
04-17 17:30:08.539 I/WindowManager(  200): createSurface Window{41881c50 SurfaceView paused=false}: DRAW NOW PENDING
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): Couldn't open /data/data/org.mozilla.fennec/files/mozilla/utj4ealf.default/browser.db for writing (will try read-only):
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): android.database.sqlite.SQLiteDatabaseLockedException: error code 5: database is locked
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.sqlite.SQLiteStatement.native_1x1_string(Native Method)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.sqlite.SQLiteStatement.simpleQueryForString(SQLiteStatement.java:161)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.DatabaseUtils.stringForQuery(DatabaseUtils.java:735)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.DatabaseUtils.stringForQuery(DatabaseUtils.java:723)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.sqlite.SQLiteDatabase.setJournalMode(SQLiteDatabase.java:1060)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:996)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.sqlite.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:1051)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:770)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:221)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:157)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.database.sqlite.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:231)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.fennec.db.BrowserProvider.getReadableDatabase(BrowserProvider.java:1005)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.fennec.db.BrowserProvider.query(BrowserProvider.java:1527)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.content.ContentProvider$Transport.query(ContentProvider.java:178)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.content.ContentResolver.query(ContentResolver.java:310)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.gecko.db.LocalBrowserDB.filterAllSites(LocalBrowserDB.java:173)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.gecko.db.LocalBrowserDB.getTopSites(LocalBrowserDB.java:194)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.gecko.db.BrowserDB.getTopSites(BrowserDB.java:119)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.gecko.AboutHomeContent.loadTopSites(AboutHomeContent.java:346)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.gecko.AboutHomeContent.access$400(AboutHomeContent.java:95)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.gecko.AboutHomeContent$9.run(AboutHomeContent.java:375)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.os.Handler.handleCallback(Handler.java:605)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.os.Handler.dispatchMessage(Handler.java:92)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at android.os.Looper.loop(Looper.java:137)
04-17 17:30:08.547 E/SQLiteOpenHelper(11552): 	at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
04-17 17:30:08.555 W/SQLiteOpenHelper(11552): Opened /data/data/org.mozilla.fennec/files/mozilla/utj4ealf.default/browser.db in read-only mode
04-17 17:30:08.656 I/ActivityManager(  200): Displayed org.mozilla.fennec/.App: +768ms
04-17 17:30:08.820 D/dalvikvm(11552): GC_FOR_ALLOC freed 148K, 2% free 15701K/15943K, paused 18ms
04-17 17:30:08.820 E/SQLiteDatabase(11552): close() was never explicitly called on database '/data/data/org.mozilla.fennec/files/mozilla/utj4ealf.default/browser.db' 
04-17 17:30:08.820 E/SQLiteDatabase(11552): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.database.sqlite.SQLiteDatabase.<init>(SQLiteDatabase.java:1943)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:1007)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:986)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.database.sqlite.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:1051)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:770)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:221)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:157)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.database.sqlite.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:231)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.fennec.db.BrowserProvider.getReadableDatabase(BrowserProvider.java:1005)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.fennec.db.BrowserProvider.query(BrowserProvider.java:1527)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.content.ContentProvider$Transport.query(ContentProvider.java:178)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.content.ContentResolver.query(ContentResolver.java:310)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.gecko.db.LocalBrowserDB.filterAllSites(LocalBrowserDB.java:173)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.gecko.db.LocalBrowserDB.getTopSites(LocalBrowserDB.java:194)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.gecko.db.BrowserDB.getTopSites(BrowserDB.java:119)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.gecko.AboutHomeContent.loadTopSites(AboutHomeContent.java:346)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.gecko.AboutHomeContent.access$400(AboutHomeContent.java:95)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.gecko.AboutHomeContent$9.run(AboutHomeContent.java:375)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.os.Handler.handleCallback(Handler.java:605)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.os.Handler.dispatchMessage(Handler.java:92)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at android.os.Looper.loop(Looper.java:137)
04-17 17:30:08.820 E/SQLiteDatabase(11552): 	at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
04-17 17:30:08.852 D/dalvikvm(11552): GC_FOR_ALLOC freed 94K, 2% free 16055K/16327K, paused 16ms

Comment 3

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

Lucas - Got another one. We can start duping these as needed

Comment 4

[Damon Sicore (:damons)]

Attachment: Portion of the log that contains a db locked exception.

Comment 6

[Lucas Rocha (:lucasr)]

Attachment: (1/2) Add native function to force unlock on database file

Comment 7

[Lucas Rocha (:lucasr)]

Attachment: Force unlock database file when database is opened in read-only mode

Comment 8

[Lucas Rocha (:lucasr)]

IIUC, sqlite on Android is using fcntl locks in the database file. In some specific situations (not easily reproducible), we get dangling file locks on the database after a crash. Those patches are an attempt to enforce file unlocking when the content provider fails to open the database file for writing (i.e. opens in read-only mode).

Given that I couldn't find a way to easily reproduce this bug, it's hard to know if these patches will actually do what we expect. Feedback is welcome.

Comment 9

[Lucas Rocha (:lucasr)]

Comment on attachment 617769 [details] [diff] [review]
(1/2) Add native function to force unlock on database file

Need to fix one more thing in this patch before requesting review.

Comment 10

[Lucas Rocha (:lucasr)]

Attachment: Add native function to force unlock on database file

Comment 11

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

Comment on attachment 617857 [details] [diff] [review]
Add native function to force unlock on database file

Review of attachment 617857 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/db/BrowserProvider.java.in
@@ +1,1 @@
> +    /* -*- Mode: Java; c-basic-offset: 4; tab-width: 20; indent-tabs-mode: nil; -*- */

don't change this

@@ +20,5 @@
>  import java.util.Random;
>  import java.util.regex.Pattern;
>  import java.util.regex.Matcher;
>  
> +import org.mozilla.gecko.GeckoAppShell;

doesn't look like this is needed

Comment 12

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

Comment on attachment 617770 [details] [diff] [review]
Force unlock database file when database is opened in read-only mode

Review of attachment 617770 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/db/BrowserProvider.java.in
@@ +21,5 @@
>  import java.util.regex.Pattern;
>  import java.util.regex.Matcher;
>  
>  import org.mozilla.gecko.GeckoAppShell;
> +import org.mozilla.gecko.GeckoAppShell;

don't need to import twice

@@ +988,5 @@
>              dbHelper = new DatabaseHelper(getContext(), getDatabasePath(profile, isTest));
>              mDatabasePerProfile.put(profile, dbHelper);
> +
> +            if (!isTest) {
> +                ensureDatabaseIsNotLocked(dbHelper, profile);

why special case tests?

Comment 13

[Lucas Rocha (:lucasr)]

Attachment: Force unlock database file when database is opened in read-only mode

Comment 14

[Lucas Rocha (:lucasr)]

Your question about the isTest special case made me realize there was a bug in my patch when running in older Android releases. New patch covers it.

Comment 15

[Lucas Rocha (:lucasr)]

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

Comment 16

[Lucas Rocha (:lucasr)]

Comment on attachment 617857 [details] [diff] [review]
Add native function to force unlock on database file

Mobile-only, beta blocker.

Comment 17

[Lucas Rocha (:lucasr)]

Comment on attachment 617926 [details] [diff] [review]
Force unlock database file when database is opened in read-only mode

Mobile-only, beta blocker.

Comment 18

[Lucas Rocha (:lucasr)]

Pushed to aurora:
https://hg.mozilla.org/releases/mozilla-aurora/rev/80a502d60a87
https://hg.mozilla.org/releases/mozilla-aurora/rev/018f6b291368

Comment 19

[Scoobidiver (away)]

It landed in 14.0a2, but not in 14.0a1 or 15.0a1. Is it wanted?

Comment 20

[:Ehsan Akhgari]

https://hg.mozilla.org/mozilla-central/rev/f4f3429d37a0
https://hg.mozilla.org/mozilla-central/rev/531323407994

Comment 21

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

(In reply to Lucas Rocha (:lucasr) from comment #18)
> Pushed to aurora:
> https://hg.mozilla.org/releases/mozilla-aurora/rev/80a502d60a87
> https://hg.mozilla.org/releases/mozilla-aurora/rev/018f6b291368

marking status-firefox=14

Comment 23

[Martijn Wargers (zombie)]

This bug is fixed, but I'm still stuck with being in this state, where I can't load any url, using Fennec. I filed bug 750739 for it.