712718 - 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)

Status: VERIFIED FIXED

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

Description

[Bill Gianopoulos [:WG9s]]

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.

Comment 1

[Matt Brubeck (:mbrubeck)]

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!

Comment 2

[Bill Gianopoulos [:WG9s]]

Attachment: catlog output

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.

Comment 3

[Bill Gianopoulos [:WG9s]]

Attachment: catlog of the entire process

This is probably what you really wanted.

Comment 4

[Matt Brubeck (:mbrubeck)]

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)

Comment 5

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

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)

Comment 6

[Gian-Carlo Pascutto [:gcp]]

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).

Comment 7

[Gian-Carlo Pascutto [:gcp]]

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)

Comment 8

[Bill Gianopoulos [:WG9s]]

(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.

Comment 10

[Gian-Carlo Pascutto [:gcp]]

Attachment: Patch 1. Move Android DB updates on the main thread

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.

Comment 11

[Gian-Carlo Pascutto [:gcp]]

Attachment: 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/[e-mail]-c5caf848b158

Comment 13

[Bill Gianopoulos [:WG9s]]

(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.

Comment 14

[Bill Gianopoulos [:WG9s]]

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.

Comment 15

[Gian-Carlo Pascutto [:gcp]]

>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?

Comment 16

[Gian-Carlo Pascutto [:gcp]]

>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.

Comment 17

[Bill Gianopoulos [:WG9s]]

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.

Comment 18

[Bill Gianopoulos [:WG9s]]

(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.

Comment 19

[Bill Gianopoulos [:WG9s]]

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.

Comment 20

[Gian-Carlo Pascutto [:gcp]]

>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.

Comment 22

[Gian-Carlo Pascutto [:gcp]]

>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.

Comment 23

[Bill Gianopoulos [:WG9s]]

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.

Comment 25

[Gian-Carlo Pascutto [:gcp]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/cd2a9f299bc1

Comment 26

[Phil Ringnalda (:philor)]

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

Comment 27

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

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

Comment 29

[Bill Gianopoulos [:WG9s]]

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 30

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

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().

Comment 31

[Gian-Carlo Pascutto [:gcp]]

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.

Comment 32

[LegNeato]

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.

Comment 33

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

https://hg.mozilla.org/releases/mozilla-aurora/rev/8f4d507c294f

Comment 34

[Martijn Wargers (dead)]

Verified fixed in today's build (2012-12-28), using the EEEPad Transformer). I used to crash, see bug 713455.

Comment 35

[Myk Melez [:myk] [@mykmelez]]

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?

Comment 36

[Gian-Carlo Pascutto [:gcp]]

Likely. Check the adb log to see where it's coming from.

Comment 37

[Myk Melez [:myk] [@mykmelez]]

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.