Closed Bug 712718 Opened 10 years ago Closed 10 years ago

Crash on startup in org.mozilla.gecko.ProfileMigrator$PlacesTask.addHistory (java.lang.RuntimeException: Can't create handler inside thread that has not called Looper.prepare)

Categories

(Firefox for Android Graveyard :: General, defect, P2)

11 Branch
ARM
Android
defect

Tracking

(firefox11 verified, firefox12 verified, fennec11+)

VERIFIED FIXED
Firefox 11
Tracking Status
firefox11 --- verified
firefox12 --- verified
fennec 11+ ---

People

(Reporter: wgianopoulos, Assigned: gcp)

References

Details

(Keywords: crash, Whiteboard: [native-crash])

Attachments

(2 files, 2 obsolete files)

I am not sure this is not expected behavior now, but stating with today's nightly build, I  can no longer run the fennec-native builds on my Samsung Galaxy Tab 8.9.

Approximately 10 seconds after launch I get a popup saying "The application Nightly (process org.mozilla.fennec) has stopped unexpectedly.  Please try again."

I am not sure if this happens with only this particular device type, or if is anything running Android version 3 or maybe anything running Android 3.1.

The 20111220 fennec-native build works fine as does the 20111221 XUL build.  SO it is definitely new today and native build only.
Can you save the system log after this happens (using the "adb" command from the Android SDK, or an app like CatLog which you can find in the Android Market) and upload it as an attachment to this bug?  Thanks!
Attached file catlog output (obsolete) —
I hope I did this right.  I basically cleared the logs got the hang, paused the logs and filteed for everything with mozilla in it.
This is probably what you really wanted.
Here's a stack trace from that log.  It looks like a problem during profile migration.

12-21 14:36:23.589 E/AndroidRuntime(4452): FATAL EXCEPTION: Thread-12
12-21 14:36:23.589 E/AndroidRuntime(4452): java.lang.RuntimeException: Can't create handler inside thread that has not called Looper.prepare()
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at android.os.Handler.<init>(Handler.java:121)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at android.webkit.WebIconDatabase$EventHandler.<init>(WebIconDatabase.java:47)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at android.webkit.WebIconDatabase$EventHandler.<init>(WebIconDatabase.java:47)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at android.webkit.WebIconDatabase.<init>(WebIconDatabase.java:44)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at android.webkit.WebIconDatabase.getInstance(WebIconDatabase.java:297)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at android.provider.Browser.truncateHistory(Browser.java:407)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at android.provider.Browser.updateVisitedHistory(Browser.java:329)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at org.mozilla.gecko.db.AndroidBrowserDB.updateVisitedHistory(AndroidBrowserDB.java:86)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at org.mozilla.gecko.db.BrowserDB.updateVisitedHistory(BrowserDB.java:96)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at org.mozilla.gecko.ProfileMigrator$PlacesTask.addHistory(ProfileMigrator.java:170)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at org.mozilla.gecko.ProfileMigrator$PlacesTask.migrateHistory(ProfileMigrator.java:202)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at org.mozilla.gecko.ProfileMigrator$PlacesTask.migratePlaces(ProfileMigrator.java:338)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at org.mozilla.gecko.ProfileMigrator$PlacesTask.run(ProfileMigrator.java:371)
12-21 14:36:23.589 E/AndroidRuntime(4452): 	at java.lang.Thread.run(Thread.java:1020)
Blocks: 699199
Summary: Today's Nightly (20111221) does not run at all on a Samsung Galaxy Tab 8.9 → Crash on startup in org.mozilla.gecko.ProfileMigrator$PlacesTask.addHistory (java.lang.RuntimeException: Can't create handler inside thread that has not called Looper.prepare)
Attachment #583565 - Attachment is obsolete: true
I have also seen some Strict Mode violations too:

E/StrictMode( 1427): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/StrictMode( 1427):    at android.database.sqlite.SQLiteCursor.<init>(SQLiteCursor.java:238)
E/StrictMode( 1427):    at android.database.sqlite.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:51)
E/StrictMode( 1427):    at android.database.sqlite.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1539)
E/StrictMode( 1427):    at android.database.sqlite.SQLiteDatabase.rawQuery(SQLiteDatabase.java:1508)
E/StrictMode( 1427):    at org.mozilla.gecko.ProfileMigrator$PlacesTask.migrateHistory(ProfileMigrator.java:185)
E/StrictMode( 1427):    at org.mozilla.gecko.ProfileMigrator$PlacesTask.migratePlaces(ProfileMigrator.java:338)
E/StrictMode( 1427):    at org.mozilla.gecko.ProfileMigrator$PlacesTask.run(ProfileMigrator.java:371)
E/StrictMode( 1427):    at java.lang.Thread.run(Thread.java:1020)

Database not closed exception:

E/SQLiteDatabase( 1427): close() was never explicitly called on database '/data/data/org.mozilla.fennec/files/mozilla/heaacgh1.default/places.sqlite'
E/SQLiteDatabase( 1427): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/SQLiteDatabase( 1427):        at android.database.sqlite.SQLiteDatabase.<init>(SQLiteDatabase.java:1980)
E/SQLiteDatabase( 1427):        at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:977)
E/SQLiteDatabase( 1427):        at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:956)
E/SQLiteDatabase( 1427):        at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:932)
E/SQLiteDatabase( 1427):        at org.mozilla.gecko.ProfileMigrator$PlacesTask.openPlaces(ProfileMigrator.java:312)
E/SQLiteDatabase( 1427):        at org.mozilla.gecko.ProfileMigrator$PlacesTask.migratePlaces(ProfileMigrator.java:336)
E/SQLiteDatabase( 1427):        at org.mozilla.gecko.ProfileMigrator$PlacesTask.run(ProfileMigrator.java:371)
E/SQLiteDatabase( 1427):        at java.lang.Thread.run(Thread.java:1020)

Uncaught exception:

I/dalvikvm( 1427): Uncaught exception thrown by finalizer (will be discarded):
I/dalvikvm( 1427): java.lang.IllegalStateException: Don't have database lock!
I/dalvikvm( 1427):      at android.database.sqlite.SQLiteDatabase.verifyLockOwner(SQLiteDatabase.java:2131)
I/dalvikvm( 1427):      at android.database.sqlite.SQLiteDatabase$1.entryRemoved(SQLiteDatabase.java:2223)
I/dalvikvm( 1427):      at android.database.sqlite.SQLiteDatabase$1.entryRemoved(SQLiteDatabase.java:2219)
I/dalvikvm( 1427):      at android.util.LruCache.trimToSize(LruCache.java:197)
I/dalvikvm( 1427):      at android.util.LruCache.evictAll(LruCache.java:285)
I/dalvikvm( 1427):      at android.database.sqlite.SQLiteDatabase.deallocCachedSqlStatements(SQLiteDatabase.java:2184)
I/dalvikvm( 1427):      at android.database.sqlite.SQLiteDatabase.closeClosable(SQLiteDatabase.java:1096)
I/dalvikvm( 1427):      at android.database.sqlite.SQLiteDatabase.finalize(SQLiteDatabase.java:1950)
I/dalvikvm( 1427):      at dalvik.system.NativeStart.run(Native Method)
Assignee: nobody → gpascutto
The strict mode violations aren't relevant. You're seeing them because the exception before it is unexpected and bypasses the existing exception handling (and db handle closing).
I'm guessing the root issue here is that the Android DB accesses aren't allowed off the main thread. (That sucks, because this means the UI will slow down while the import happens)
(In reply to Gian-Carlo Pascutto (:gcp) from comment #7)
> I'm guessing the root issue here is that the Android DB accesses aren't
> allowed off the main thread. (That sucks, because this means the UI will
> slow down while the import happens)

Well, as I said in the first comment, the issue could be version dependent.  This was on a tablet running Android Honeycomb 3.1.
Keywords: crash
Whiteboard: [native-crash]
Duplicate of this bug: 712719
This moves all the DB updates onto the main thread. This is nasty and will produce lots of StrictMode errors because it involves disk I/O. But it's also what the trace in comment 4 suggests. I'd like confirmation this at least fixes the issue for people who experience it.
Attachment #583680 - Flags: review?(doug.turner)
So, it looks like this is really hitting this bug in Android: http://code.google.com/p/android/issues/detail?id=11291

If I understand correctly, the attached patch may by sufficient as a workaround. Again, can someone who was seeing the original issue try it? 

There's a try build (arriving shortly) here:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/gpascutto@mozilla.com-c5caf848b158
Attachment #583689 - Flags: review?(doug.turner)
Priority: -- → P2
Duplicate of this bug: 712984
(In reply to Gian-Carlo Pascutto (:gcp) from comment #11)
> Created attachment 583689 [details] [diff] [review]
> Patch 2. Try to force handler creation on main thread (workaround Android
> bug)
> 
> So, it looks like this is really hitting this bug in Android:
> http://code.google.com/p/android/issues/detail?id=11291
> 
> If I understand correctly, the attached patch may by sufficient as a
> workaround. Again, can someone who was seeing the original issue try it? 
> 
> There's a try build (arriving shortly) here:
> http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/gpascutto@mozilla.
> com-c5caf848b158

This try version corrects the issue for me.
Hmm but the news is not all good.  I would have thought that once I used the try build to migrate the profile, that the regular nightly would then run with no issue.  This does not appear to be the case.  So, it would seem it is not setting anything in the profile to indicate it was already migrating and doing this on each startup.  This would seem to be a large waste of time and startup time issue.
>So, it would seem it is not setting anything in the profile to indicate it was 
>already migrating and doing this on each startup.

*If* the migration finishes successfully, the old database is deleted. Can you check your logs if there are no other exceptions/failures during the migration?
>This would seem to be a large waste of time and startup time issue.

Note that, aside from running only once, the code only launches in the background after startup. It will not affect startup time in any case.
Oh, so it the presence of the old database is enough to trigger this then this is probably not an issue for real users, but is still an issue for testers like me who are running nightly, beta release and Aurora builds because I am doing nightly testing.
(In reply to Gian-Carlo Pascutto (:gcp) from comment #16)
> >This would seem to be a large waste of time and startup time issue.
> 
> Note that, aside from running only once, the code only launches in the
> background after startup. It will not affect startup time in any case.

But even running in the background, it would probably effect performance of the browser while it is running.
So, I have no idea if that issue is worth worrying about, just wanted to mention it to see if I should file a new bug on it.
>Oh, so it the presence of the old database is enough to trigger this then this is 
>probably not an issue for real users, but is still an issue for testers like me 
>who are running nightly, beta release and Aurora builds because I am doing nightly 
>testing.

Nightly, Beta and Aurora all install in different Android folders, as a different application, so you will not see migration between them. You will only see migration if you (for example) replace your XUL Nightly with a Native Nightly, and then the migration should happen a bit after your first launch.

>But even running in the background, it would probably effect performance of the 
>browser while it is running.

Right.
Duplicate of this bug: 713155
>So, I have no idea if that issue is worth worrying about, just wanted to mention 
>it to see if I should file a new bug on it.

If your operations were like:

1) Use XUL build
2) Switch to Native
3) See crash
4) Use try build mentioned here, crash gone
5) Switch back to build of (2), crash again

then there is a problem. You can help diagnosing by checking the logcat during step (4) to see if there are no other errors/exceptions.
What I did , which was probably stupid, was I tested the try build everything was fine, then I used the Firefox release version 9 to go find the latest nightly so made a new old style data store.

This is why I said this probably wont be a real issue for real users, once it lands.
Duplicate of this bug: 713272
Attachment #583689 - Flags: review?(doug.turner) → review+
https://hg.mozilla.org/mozilla-central/rev/cd2a9f299bc1
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 12
Comment on attachment 583689 [details] [diff] [review]
Patch 2. Try to force handler creation on main thread (workaround Android bug)

Need to fix the same crash on aurora
Attachment #583689 - Flags: approval-mozilla-aurora?
Duplicate of this bug: 713455
Same crash occurs on Aurora.  Seems not to be a huge impact on  he code.  It has been proven on Nightly to avoid the crash.
Comment on attachment 583680 [details] [diff] [review]
Patch 1. Move Android DB updates on the main thread

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

::: mobile/android/base/ProfileMigrator.java
@@ +239,5 @@
>                          }
>                      }
> +            });
> +            // And Android DB access must be on the UI thread
> +            GeckoAppShell.getMainHandler().post(new Runnable() {

what makes you think they need to be run on the main UI thread? That error is just about not being run on a thread with a looper. Please use GeckoAppShell.getHandler().
Attachment #583680 - Flags: review?(doug.turner) → review-
Comment on attachment 583680 [details] [diff] [review]
Patch 1. Move Android DB updates on the main thread

The Android issue mentioned in comment 11 explains why this is overkill. Patch 2 should be sufficient.
Attachment #583680 - Attachment is obsolete: true
Version: Trunk → Firefox 11
Comment on attachment 583689 [details] [diff] [review]
Patch 2. Try to force handler creation on main thread (workaround Android bug)

[triage comment]
Approved for aurora. Fixes a startup crash with Native UI.
Attachment #583689 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Verified fixed in today's build (2012-12-28), using the EEEPad Transformer). I used to crash, see bug 713455.
Status: RESOLVED → VERIFIED
tracking-fennec: --- → 11+
Erm, I still see a crash on startup after a few seconds if I do nothing after starting Aurora (i.e. I remain on the Aurora Start page).  If I tap in the location bar, however, the crash does not occur.  Different bug?
Likely. Check the adb log to see where it's coming from.
Hmm, I haven't been able to reproduce it in the last couple nightlies (including today's), so I'll let this particular sleeping dog lie until I see it again, at which point I'll check the log and reopen this bug or file a new one as appropriate.
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.