Closed Bug 746444 Opened 11 years ago Closed 11 years ago

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

Categories

(Firefox for Android Graveyard :: General, defect)

ARM
Android
defect
Not set
normal

Tracking

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

RESOLVED FIXED
Firefox 15
Tracking Status
firefox14 --- fixed
blocking-fennec1.0 --- beta+

People

(Reporter: kbrosnan, Assigned: lucasr)

References

Details

Attachments

(5 files, 2 obsolete files)

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
Attached file Another full log
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+
Attachment #617769 - Flags: review?(blassey.bugs)
Attachment #617770 - 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)
Attachment #617857 - 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: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 15
Whiteboard: [inbound]
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.
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.