752907 - Gecko crashes on the first run after an update XUL->Native

Status: RESOLVED DUPLICATE of bug 750950

(Firefox for Android Graveyard :: General, defect)

Description

[Cristian Nicolae (:xti)]

Attachment: logs_nexus

Firefox 15.0a1 (2012-05-07)
Device: Samsung Galaxy Nexus
OS: Android 4.0.2

Steps to reproduce:
1. Install the latest Nightly XUL build
2. Open Fennec and perform Sync
3. Wait until Sync is done and close Fennec
4. Upgrade Fennec to the latest Native Nightly build
5. Open Fennec
6. Go to Android Settings > Accounts and Sync > Firefox Sync account

Expected result:
Firefox Sync account is listed and it's working without any issues.

Actual result:
Firefox Sync account is missing. Please see attached logs for more details.

Comment 1

[Gian-Carlo Pascutto [:gcp]]

We crashed on the first run, apparently before Gecko was able to reply to the Java UI with the Sync settings.

There seems to be some stuff missing from this log, though? I'd expected to see Telemetry etc.

I/GeckoAppShell(28449): XRE exited
I/GeckoAppShell(28449): we're done, good bye
W/GeckoAppShell(28449): Killing via System.exit()
F/libc    (28449): Fatal signal 11 (SIGSEGV) at 0x5b82d018 (code=1)
D/dalvikvm( 1942): GC_CONCURRENT freed 2232K, 27% free 31766K/43015K, paused 1ms+21ms
I/ActivityManager(  197): Process org.mozilla.fennec (pid 28449) has died.
I/WindowManager(  197): WIN DEATH: Window{41e53510 org.mozilla.fennec/org.mozilla.fennec.App paused=true}
W/WindowManager(  197): Force-removing child win Window{420e36c8 SurfaceView paused=false} from container Window{41e53510 org.mozilla.fennec/org.mozilla.fennec.App paused=true}
I/DEBUG   (23120): debuggerd committing suicide to free the zombie!
I/DEBUG   (28867): debuggerd: Dec  8 2011 16:19:20

Comment 2

[Gian-Carlo Pascutto [:gcp]]

What happens if you restart Fennec? 

I see no evidence of dataloss in the log, because a crash before Sync migration has happened will not mark that migration as finished, so it'll retry on the next run.

Please re-set the flag if I'm wrong.

Comment 3

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

I found this crash from the Profile Migrator in the logcat:

I/ProfileMigrator(28449): Iteration = 1, added 445 bookmark(s), skipped 67 bookmark(s)
D/dalvikvm(28449): GC_CONCURRENT freed 826K, 5% free 17304K/18183K, paused 2ms+4ms
W/ProfileMigrator(28449): Orphaned bookmarks found, not imported
I/ProfileMigrator(28449): Iteration = 2, added 66 bookmark(s), skipped 1 bookmark(s)
I/ProfileMigrator(28449): Flushing 312 DB operations
W/GeckoBrowserProvider(28449): SQLite Exception during applyBatch: 
W/GeckoBrowserProvider(28449): android.database.sqlite.SQLiteConstraintException: error code 19: constraint failed
W/GeckoBrowserProvider(28449): 	at android.database.sqlite.SQLiteStatement.native_execute(Native Method)
W/GeckoBrowserProvider(28449): 	at android.database.sqlite.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:92)
W/GeckoBrowserProvider(28449): 	at android.database.sqlite.SQLiteDatabase.updateWithOnConflict(SQLiteDatabase.java:1810)
W/GeckoBrowserProvider(28449): 	at android.database.sqlite.SQLiteDatabase.update(SQLiteDatabase.java:1761)
W/GeckoBrowserProvider(28449): 	at org.mozilla.fennec.db.BrowserProvider.updateImage(BrowserProvider.java:2016)
W/GeckoBrowserProvider(28449): 	at org.mozilla.fennec.db.BrowserProvider.updateExistingImage(BrowserProvider.java:1990)
W/GeckoBrowserProvider(28449): 	at org.mozilla.fennec.db.BrowserProvider.updateInTransaction(BrowserProvider.java:1445)
W/GeckoBrowserProvider(28449): 	at org.mozilla.fennec.db.BrowserProvider.update(BrowserProvider.java:1362)
W/GeckoBrowserProvider(28449): 	at android.content.ContentProviderOperation.apply(ContentProviderOperation.java:225)
W/GeckoBrowserProvider(28449): 	at org.mozilla.fennec.db.BrowserProvider.applyBatch(BrowserProvider.java:2135)
W/GeckoBrowserProvider(28449): 	at android.content.ContentProvider$Transport.applyBatch(ContentProvider.java:208)
W/GeckoBrowserProvider(28449): 	at android.content.ContentProviderClient.applyBatch(ContentProviderClient.java:120)
W/GeckoBrowserProvider(28449): 	at android.content.ContentResolver.applyBatch(ContentResolver.java:766)
W/GeckoBrowserProvider(28449): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.flushBatchOperations(ProfileMigrator.java:1157)
W/GeckoBrowserProvider(28449): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.migrateBookmarks(ProfileMigrator.java:1150)
W/GeckoBrowserProvider(28449): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.migratePlaces(ProfileMigrator.java:1208)
W/GeckoBrowserProvider(28449): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.run(ProfileMigrator.java:1250)
W/GeckoBrowserProvider(28449): 	at org.mozilla.gecko.ProfileMigrator.launchPlaces(ProfileMigrator.java:299)
W/GeckoBrowserProvider(28449): 	at org.mozilla.gecko.ProfileMigrator.launchPlaces(ProfileMigrator.java:290)
W/GeckoBrowserProvider(28449): 	at org.mozilla.gecko.GeckoApp$39.run(GeckoApp.java:2277)
W/GeckoBrowserProvider(28449): 	at android.os.Handler.handleCallback(Handler.java:605)
W/GeckoBrowserProvider(28449): 	at android.os.Handler.dispatchMessage(Handler.java:92)
W/GeckoBrowserProvider(28449): 	at android.os.Looper.loop(Looper.java:137)
W/GeckoBrowserProvider(28449): 	at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
D/dalvikvm(28449): GC_CONCURRENT freed 1136K, 7% free 17169K/18439K, paused 3ms+3ms
D/AccountTypeManager(28713): Registering external account type=com.facebook.auth.login, packageName=com.facebook.katana
D/dalvikvm(28605): GC_CONCURRENT freed 235K, 3% free 14531K/14855K, paused 59ms+1ms
D/dalvikvm(28713): GC_CONCURRENT freed 230K, 3% free 14238K/14599K, paused 47ms+1ms
D/dalvikvm(28449): GC_CONCURRENT freed 973K, 7% free 17248K/18439K, paused 1ms+4ms
I/ProfileMigrator(28449): Error while applying database updates: 
I/ProfileMigrator(28449): android.content.OperationApplicationException
I/ProfileMigrator(28449): 	at org.mozilla.fennec.db.BrowserProvider.applyBatch(BrowserProvider.java:2167)
I/ProfileMigrator(28449): 	at android.content.ContentProvider$Transport.applyBatch(ContentProvider.java:208)
I/ProfileMigrator(28449): 	at android.content.ContentProviderClient.applyBatch(ContentProviderClient.java:120)
I/ProfileMigrator(28449): 	at android.content.ContentResolver.applyBatch(ContentResolver.java:766)
I/ProfileMigrator(28449): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.flushBatchOperations(ProfileMigrator.java:1157)
I/ProfileMigrator(28449): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.migrateBookmarks(ProfileMigrator.java:1150)
I/ProfileMigrator(28449): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.migratePlaces(ProfileMigrator.java:1208)
I/ProfileMigrator(28449): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.run(ProfileMigrator.java:1250)
I/ProfileMigrator(28449): 	at org.mozilla.gecko.ProfileMigrator.launchPlaces(ProfileMigrator.java:299)
I/ProfileMigrator(28449): 	at org.mozilla.gecko.ProfileMigrator.launchPlaces(ProfileMigrator.java:290)
I/ProfileMigrator(28449): 	at org.mozilla.gecko.GeckoApp$39.run(GeckoApp.java:2277)
I/ProfileMigrator(28449): 	at android.os.Handler.handleCallback(Handler.java:605)
I/ProfileMigrator(28449): 	at android.os.Handler.dispatchMessage(Handler.java:92)
I/ProfileMigrator(28449): 	at android.os.Looper.loop(Looper.java:137)
I/ProfileMigrator(28449): 	at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)

Comment 4

[Gian-Carlo Pascutto [:gcp]]

That is not a crash, that exception is expected, caught and handled. They are due to bug 717428. The cause is elsewhere.

Comment 5

[Aaron Train [:aaronmt]]

Unable to reproduce with Nightly (05/08), Galaxy Nexus (4.0.4) and Sony Ericsson Xperia Play (2.3).

Comment 6

[:Margaret Leibovic]

Attachment: logcat (Nexus S)

I can reproduce with the latest XUL/Android Nightly builds on my Galaxy S (2.3.6). I'm finding that after profile migration appears to run, I end up with an empty about:home screen, and the app dies when I try to interact with it. Then, after restarting Nightly, none of my XUL data is present.

The relevant error looks like:
I/ProfileMigrator( 1410): Error while applying database updates: 
I/ProfileMigrator( 1410): android.content.OperationApplicationException: insert failed
I/ProfileMigrator( 1410): 	at android.content.ContentProviderOperation.apply(ContentProviderOperation.java:216)
I/ProfileMigrator( 1410): 	at org.mozilla.fennec.db.BrowserProvider.applyBatch(BrowserProvider.java:2135)
I/ProfileMigrator( 1410): 	at android.content.ContentProvider$Transport.applyBatch(ContentProvider.java:217)
I/ProfileMigrator( 1410): 	at android.content.ContentProviderClient.applyBatch(ContentProviderClient.java:95)
I/ProfileMigrator( 1410): 	at android.content.ContentResolver.applyBatch(ContentResolver.java:639)
I/ProfileMigrator( 1410): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.flushBatchOperations(ProfileMigrator.java:1157)
I/ProfileMigrator( 1410): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.migrateBookmarks(ProfileMigrator.java:1105)
I/ProfileMigrator( 1410): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.migratePlaces(ProfileMigrator.java:1208)
I/ProfileMigrator( 1410): 	at org.mozilla.gecko.ProfileMigrator$PlacesRunnable.run(ProfileMigrator.java:1250)
I/ProfileMigrator( 1410): 	at org.mozilla.gecko.ProfileMigrator.launchPlaces(ProfileMigrator.java:299)
I/ProfileMigrator( 1410): 	at org.mozilla.gecko.ProfileMigrator.launchPlaces(ProfileMigrator.java:290)
I/ProfileMigrator( 1410): 	at org.mozilla.gecko.GeckoApp$39.run(GeckoApp.java:2276)
I/ProfileMigrator( 1410): 	at android.os.Handler.handleCallback(Handler.java:587)
I/ProfileMigrator( 1410): 	at android.os.Handler.dispatchMessage(Handler.java:92)
I/ProfileMigrator( 1410): 	at android.os.Looper.loop(Looper.java:130)
I/ProfileMigrator( 1410): 	at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)

Comment 7

[Gian-Carlo Pascutto [:gcp]]

Margaret, please see comment 4 that I just addressed at mfinkle.

Comment 8

[:Margaret Leibovic]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #7)
> Margaret, please see comment 4 that I just addressed at mfinkle.

/me hangs head in shame.

In other news, I found that when I created a new profile/sync account, I couldn't reproduce this issue anymore. Luckily, the profile I was using before was a pretty small and recently created test profile, so hopefully we can use that to figure out what's going wrong. If you want to use it to test, I put it here:
http://people.mozilla.com/~mleibovic/tmp/2ymt116p.test.zip

Comment 9

[:Margaret Leibovic]

Attachment: logcat (without crash this time, but still no sync migration)

I realized that even though the migration with a new profile/sync account didn't have the same crash and more severe migration fail, my sync setting still didn't get migrated.

I suppose we should focus on the sync migration bit in this bug, and worry about the crashiness in a separate bug.

Comment 10

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

removing QAwanted as Margaret found that she can reproduce with her profile; regression window is still wanted.

Comment 11

[Gian-Carlo Pascutto [:gcp]]

The non-crashing log has a race condition in preferences:

D/ProfileMigrator( 1410): Received event: Preferences:Data
W/ProfileMigrator( 1410): Could not recover setting for = ui.zooming.animation_frames

Sync migration sends a preference request to Gecko and registers a listener for the reply. It actually gets a reply from a preference somebody else requested, then proceeds to try to parse it and unregisters itself and attempts to set up.

It should not unregister its preference listener until it actually received a reply to its own request.

This explains why at least margaret's non-crash failed to set up Sync. It doesn't explain the crashers - they don't get to this point to begin with.

Comment 12

[Gian-Carlo Pascutto [:gcp]]

Created bug 753175 for the race condition. This bug has the flags already nicely set for the crashers, so let's keep them here.

Comment 13

[Richard Newman [:rnewman]]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #11)
> Sync migration sends a preference request to Gecko and registers a listener
> for the reply. It actually gets a reply from a preference somebody else
> requested, then proceeds to try to parse it and unregisters itself and
> attempts to set up.

So I imagine that could cause Bug 752514 (where Sync is apparently given an invalid username or password), right?

Comment 14

[Gian-Carlo Pascutto [:gcp]]

No, Sync won't even be contacted if we fail to receive settings to get it. You can see this in Margaret's log:

E/ProfileMigrator( 1884): Profile has incomplete Sync config. Not migrating.

Comment 15

[Gian-Carlo Pascutto [:gcp]]

I'm trying to reproduce this using Margarets profile.

1) Install XUL Fennec
2) Wipe contents of old profile, copy margarets data into it.
3) Install Native Fennec
4) Launch

I can't reproduce the exact problems here, but I hit another *two* *different* issues :(

Strange failure decoding Sync passwords:
http://pastebin.mozilla.org/1628006

Strictmode violation:
E/StrictMode(23606):    at org.mozilla.gecko.Favicons$LoadFaviconTask.downloadFavicon(Favicons.java:288)

No crash and a valid profile (minus Sync, obviously)

Comment 16

[:Margaret Leibovic]

Update: After building with my patch for bug 753175, I can't reproduce the same hang/crash issue I was seeing. I did find a sync problem, but it doesn't seem to be related to our migration code, so I filed it as bug 753464 (I experienced this with both of the profiles/sync accounts I was using for testing).

I'm not quite sure what the status of this bug should be, since there's a whole bunch of different issues reported in here, the first of which was fixed by bug 753175. Unless someone can reproduce a crash on first run after XUL->Native migration, I think we can probably close this bug as a dupe of bug 753175, but make sure all the unrelated issues are filed separately.

Comment 17

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

Can we retest this bug after bug bug 753175 lands on m-c? Also test on aurora, where the patch has already landed.

Comment 18

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

Attachment: XUL to Native Logcat on Samsung Galaxy S II

Wierd.  This might be a separate bug.

STR:
1) have native nightly installed w/ Sync setup
2) uninstall any nightly
3) install XUL nightly 5/8/2012
4) go to ilm.com and bookmark
5) quit
6) adb install -r fennec-15.0a1.en-US.nightly_05_08_2012.apk 
7) look in awesome page for ilm.com bookmark

Expected: ilm.com bookmark in the bookmark category
Actual: Top sites and History shows www.ilm.com bookmarked; Bookmarks does not show www.ilm.com in any folder

It tried to Sync my desktop w/ nothing... I see a Desktop Bookmarks folder instead of my default bookmarks

Within my log I found this:
05-10 06:56:03.140: I/dalvikvm(30473): Could not find method android.database.sqlite.SQLiteDatabase.enableWriteAheadLogging, referenced from method org.mozilla.fennec.db.BrowserProvider$DatabaseHelper.onOpen
05-10 06:56:03.140: W/dalvikvm(30473): VFY: unable to resolve virtual method 277: Landroid/database/sqlite/SQLiteDatabase;.enableWriteAheadLogging ()Z
05-10 06:56:03.140: D/dalvikvm(30473): VFY: replacing opcode 0x6e at 0x0033

As well as this :
05-10 06:56:03.605: V/Telemetry(30473): Sending telemetry: {"value":11,"name":"BROWSERPROVIDER_XUL_IMPORT_BOOKMARKS"}
05-10 06:56:03.605: I/ProfileMigrator(30473): Flushing 1 DB operations

Comment 19

[Gian-Carlo Pascutto [:gcp]]

That's bug 752444.

Comment 20

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

Oh oops.  I put it in the wrong bug.  Sorry.

Comment 21

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

Margaret, looking at your log from comment 6... it looks like you force quit?

I/InputDispatcher(  111): Dropping event because the pointer is not down.
I/InputDispatcher(  111): Dropping event because the pointer is not down.
I/InputDispatcher(  111): Dropping event because the pointer is not down.
W/ActivityManager(  111):   Force finishing activity org.mozilla.fennec/.App
I/Process (  111): Sending signal. PID: 1410 SIG: 9
I/ActivityManager(  111): Killing org.mozilla.fennec (pid=1410): user's request
I/ActivityManager(  111): Process org.mozilla.fennec (pid 1410) has died.

Comment 22

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

I see the same in Nicolae's log...  Could it be that the sync was interrupted by the installation of Fennec Native?

I/Process (  197): Sending signal. PID: 27359 SIG: 9
I/ActivityManager(  197): Force stopping package org.mozilla.fennec uid=10116
I/ActivityManager(  197):   Force finishing activity ActivityRecord{4183ae48 org.mozilla.fennec/.App}
W/InputManagerService(  197): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@41838da0
I/WindowManager(  197): WIN DEATH: Window{421c11d0 org.mozilla.fennec/org.mozilla.fennec.App paused=true}
W/WindowManager(  197): Force-removing child win Window{421c1570 SurfaceView paused=false} from container Window{421c11d0 org.mozilla.fennec/org.mozilla.fennec.App paused=true}
D/dalvikvm(27224): GC_CONCURRENT freed 372K, 5% free 15403K/16135K, paused 1ms+2ms
D/dalvikvm(27224): GC_CONCURRENT freed 648K, 7% free 15166K/16135K, paused 2ms+2ms
D/OpenGLRenderer(27494): Flushing caches (mode 1)
D/dalvikvm(27224): GC_CONCURRENT freed 276K, 5% free 15395K/16135K, paused 2ms+2ms
D/OpenGLRenderer(27494): Flushing caches (mode 1)
D/Smack   (24852): [SSLXMPPConnection@1101851640] create socket connection(mtalk.google.com, 5228)
D/dalvikvm(27224): GC_CONCURRENT freed 561K, 6% free 15250K/16135K, paused 1ms+4ms
D/dalvikvm(27224): GC_CONCURRENT freed 467K, 6% free 15196K/16135K, paused 2ms+2ms
D/dalvikvm(27536): GC_CONCURRENT freed 818K, 4% free 25167K/26119K, paused 1ms+5ms
D/dalvikvm(27224): GC_CONCURRENT freed 371K, 6% free 15215K/16135K, paused 2ms+2ms
D/dalvikvm(27224): GC_CONCURRENT freed 375K, 6% free 15254K/16135K, paused 2ms+2ms
D/dalvikvm(27224): GC_CONCURRENT freed 231K, 5% free 15424K/16135K, paused 1ms+2ms
D/dalvikvm(27224): GC_FOR_ALLOC freed 120K, 5% free 15485K/16135K, paused 18ms
D/dalvikvm(27553): GC_CONCURRENT freed 420K, 4% free 14041K/14535K, paused 6ms+2ms
I/WindowManager(  197): createSurface Window{41f249d8 com.android.settings/com.android.settings.SubSettings paused=false}: DRAW NOW PENDING
I/InstalledAppDetails(27536): Clearing user data for package : org.mozilla.fennec
I/ActivityManager(  197): Force stopping package org.mozilla.fennec uid=10116
I/InstalledAppDetails(27536): Cleared user data for package : org.mozilla.fennec
W

Comment 23

[:Margaret Leibovic]

(In reply to Naoki Hirata :nhirata from comment #21)
> Margaret, looking at your log from comment 6... it looks like you force quit?
> 
> I/InputDispatcher(  111): Dropping event because the pointer is not down.
> I/InputDispatcher(  111): Dropping event because the pointer is not down.
> I/InputDispatcher(  111): Dropping event because the pointer is not down.
> W/ActivityManager(  111):   Force finishing activity org.mozilla.fennec/.App
> I/Process (  111): Sending signal. PID: 1410 SIG: 9
> I/ActivityManager(  111): Killing org.mozilla.fennec (pid=1410): user's
> request
> I/ActivityManager(  111): Process org.mozilla.fennec (pid 1410) has died.

I got an "application stopped responding" dialog, and then killed the app from that. I never experienced normal crash, only a hang that resulted in needing to kill the app.

Also, the app never got to the point of showing top sites on about:home, which makes my issue sound a lot like bug 750950. However, I bet there are multiple things that could happen that could cause the app to die before about:home gets filled.

Comment 24

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

Ok, thanks for the explanation.  I'll try again to repro.

Comment 25

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

(In reply to Naoki Hirata :nhirata from comment #24)
> Ok, thanks for the explanation.  I'll try again to repro.

If anyone has been able to reproduce this, please try again using a Nightly. A few other, related bugs have been fixed and might affect this one.

Comment 26

[JP Rosevear [:jpr]]

Naoki, have you been able to re-test?  Would like to know if we have work to do for beta 2 or not.

Comment 27

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

Attachment: screenshot

I retested with Margaret's profile.  The session restore had some issues with it and I hung when trying to setup sync without having upgraded to native.  The issue happened before even trying to upgrade.

Based on this, I don't think it's a fennec native/migration issue per se, I think it has to do with this profile and sync in general.  Once I got out of the sync hanging by killing xul fennec, I was able to migrate to native just fine.

To note, I tried avoiding the error message about the profile by change moding to 777 for everything in the profile... the only way to avoid it is just to wait 30 seconds and then quit fennec and reopen.

Comment 28

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

Attachment: logcat

Comment 29

[:Margaret Leibovic]

Duping to bug 750950, since it looks like that fix resolved this issue.

Comment 30

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

removing qawanted and regressionwindow wanted due to this being duped off to bug 750950