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

RESOLVED FIXED in Firefox 14

Status

()

defect
RESOLVED FIXED
7 years ago
7 years ago

People

(Reporter: kbrosnan, Assigned: lucasr)

Tracking

Trunk
Firefox 15
ARM
Android
Points:
---

Firefox Tracking Flags

(firefox14 fixed, blocking-fennec1.0 beta+)

Details

Attachments

(5 attachments, 2 obsolete attachments)

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
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
Lucas - Got another one. We can start duping these as needed
Assignee: nobody → lucasr.at.mozilla
blocking-fennec1.0: ? → beta+
Duplicate of this bug: 741718
Attachment #617769 - Flags: review?(blassey.bugs)
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 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.
Attachment #617769 - Attachment is obsolete: true
Attachment #617769 - Flags: review?(blassey.bugs)
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
Attachment #617857 - Flags: review?(blassey.bugs) → review+
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?
Attachment #617770 - Flags: review?(blassey.bugs) → review+
Attachment #617770 - Attachment is obsolete: true
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.
Attachment #617926 - Flags: review?(blassey.bugs) → review+
Comment on attachment 617857 [details] [diff] [review]
Add native function to force unlock on database file

Mobile-only, beta blocker.
Attachment #617857 - Flags: approval-mozilla-aurora?
Comment on attachment 617926 [details] [diff] [review]
Force unlock database file when database is opened in read-only mode

Mobile-only, beta blocker.
Attachment #617926 - Flags: approval-mozilla-aurora?
Attachment #617857 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #617926 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Whiteboard: [inbound]
It landed in 14.0a2, but not in 14.0a1 or 15.0a1. Is it wanted?
https://hg.mozilla.org/mozilla-central/rev/f4f3429d37a0
https://hg.mozilla.org/mozilla-central/rev/531323407994
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 15
Whiteboard: [inbound]
Duplicate of this bug: 741718
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.
You need to log in before you can comment on or make changes to this bug.