751646 - Timeout executing service: ServiceRecord (org.mozilla.gecko.sync.syncadapter.SyncService)

Status: RESOLVED WORKSFORME

(Firefox for Android Graveyard :: General, defect)

Description

[Gian-Carlo Pascutto [:gcp]]

From bug 721934 comment 63:

05-03 17:19:42.758: W/ActivityManager(101): Timeout executing service: ServiceRecord{46549af8 org.mozilla.fennec/org.mozilla.gecko.sync.syncadapter.SyncService}
05-03 17:19:42.794: E/ActivityManager(101): ANR in org.mozilla.fennec
05-03 17:19:42.794: E/ActivityManager(101): Reason: Executing service org.mozilla.fennec/org.mozilla.gecko.sync.syncadapter.SyncService
05-03 17:19:42.794: E/ActivityManager(101): Load: 1.58 / 1.57 / 0.75
05-03 17:19:42.794: E/ActivityManager(101): CPU usage from 10318ms to 33ms ago:
05-03 17:19:42.794: E/ActivityManager(101):   system_server: 1% = 0% user + 0% kernel / faults: 32 minor
05-03 17:19:42.794: E/ActivityManager(101):   e.process.gapps: 0% = 0% user + 0% kernel / faults: 278 minor
05-03 17:19:42.794: E/ActivityManager(101):   akmd: 0% = 0% user + 0% kernel
05-03 17:19:42.794: E/ActivityManager(101):   events/0: 0% = 0% user + 0% kernel
05-03 17:19:42.794: E/ActivityManager(101):  +flush-31:0: 0% = 0% user + 0% kernel
05-03 17:19:42.794: E/ActivityManager(101): TOTAL: 2% = 1% user + 0% kernel
05-03 17:19:42.804: I/Process(101): Sending signal. PID: 755 SIG: 3

Comment 1

[Richard Newman [:rnewman]]

What looks like is happening here:

* Android decides to sync. There is no Fennec process, so it starts one.

05-03 17:19:02.454: I/ActivityManager(101): Start proc org.mozilla.fennec_aurora for service org.mozilla.fennec_aurora/org.mozilla.gecko.sync.syncadapter.SyncService: pid=823 uid=10064 gids={3003, 1015, 1006}

* It has to publish all of Fennec's CPs in order to do so.

05-03 17:19:02.524: I/ActivityThread(823): Publishing provider org.mozilla.fennec_aurora.db.browser: org.mozilla.fennec_aurora.db.BrowserProvider
05-03 17:19:02.594: I/ActivityThread(823): Publishing provider org.mozilla.fennec_aurora.db.tabs: org.mozilla.fennec_aurora.db.TabsProvider
05-03 17:19:02.614: I/ActivityThread(823): Publishing provider org.mozilla.fennec_aurora.db.formhistory: org.mozilla.fennec_aurora.db.FormHistoryProvider

* SyncAdapter calls AccountManager.get to get your credentials, and waits for the callback:

05-03 17:19:02.674: D/SyncAdapter(823): AccountManager.get(org.mozilla.gecko.GeckoApplication@462958a0)

* 30 seconds later, it times out without ever getting the callback.

05-03 17:19:42.758: W/ActivityManager(101): Timeout executing service: ServiceRecord{46549af8 org.mozilla.fennec/org.mozilla.gecko.sync.syncadapter.SyncService}


GeckoApp shouldn't be the context here, which is kinda weird, but other than that this looks like an "Android sucks" bug -- we're sitting and waiting on an Android system call that never returns.

Would need more reports to think that this is a real issue.

Comment 2

[Gian-Carlo Pascutto [:gcp]]

Could there be some interaction with Sync migration here? This was the users first run.

Comment 3

[Richard Newman [:rnewman]]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #2)
> Could there be some interaction with Sync migration here? This was the users
> first run.

Android will try to sync when an account is created, yes, including through migration. I don't know why that would cause the account query to time out.

Comment 4

[Richard Newman [:rnewman]]

No point blocking on this unless QA can demonstrate that it's reproducible.

Comment 5

[Adrian Tamas (:AdrianT)]

Attachment: log HTC Desire Z (Android 2.3)

Comment 6

[Adrian Tamas (:AdrianT)]

Attachment: log Samsung Galaxy S2 (Android 2.3.4)

Comment 7

[Adrian Tamas (:AdrianT)]

Attachment: log Motorola Droid Pro (Android 2.3.4)

Comment 8

[Adrian Tamas (:AdrianT)]

Issue is reproducible on Motorola Droid Pro (Android 2.3.4), HTC Desire (Android 2.2), HTC Desire Z (Android 2.3.3), Samsung Galaxy S2 (Android 2.3.4) using Nightly XUL and Nightly Native for 2012-05-03 but only with my profile. The total profile size is 3.1 MB.

Comment 9

[Richard Newman [:rnewman]]

Thanks, Adrian. When you say "only with my profile", does that mean that you tried with others without reproducing the bug? If so, can you outline any differences between those that failed and those that succeeded?

Comment 10

[Richard Newman [:rnewman]]

Adrian, your log suggests that you have more than one version of Firefox installed.

05-04 10:27:44.660: DEBUG/PackageManager(2706): Scanning package org.mozilla.fennec
05-04 10:27:44.660: DEBUG/PackageManager(2706): Shared UserID org.mozilla.fennec.sharedID (uid=10134): packages=[PackageSetting{40d5f9e0 org.mozilla.fennec/10134}, PackageSetting{40611578 org.mozilla.fennec_aurora/10134}]
05-04 10:27:44.660: INFO/PackageManager(2706): Package org.mozilla.fennec codePath changed from /data/app/org.mozilla.fennec-1.apk to /data/app/org.mozilla.fennec-2.apk; Retaining data and using new

Could you try again with only one version installed?

Comment 11

[Adrian Tamas (:AdrianT)]

I am able to reproduce the issue using only one Firefox app installed (Nightly).
The issue was reproduced using only one account. I have created a new one using the data from this account but I am unable to reproduce the issue using the new account leading me to believe that the data does not influence this bug.

Comment 12

[Richard Newman [:rnewman]]

(In reply to adrian tamas from comment #11)
> I am able to reproduce the issue using only one Firefox app installed
> (Nightly).

Can you provide a log with only a single instance installed?

Do you have STR?

Comment 13

[Adrian Tamas (:AdrianT)]

Attachment: logs with only one version of Fennec installed

Comment 14

[Adrian Tamas (:AdrianT)]

Steps to reproduce:
1. Install Nightly XUL 15.0a1.
2. Set up a profile sync on the device and wait for the data to be synced.
3. Download and install Nightly Native 15.0a1
4. Tap the Open button and wait for Nightly to start.

Actual:
After a few minutes I get a "Force close" dialog. Tapping on Wait to continue setting up Nightly just leaves the app standing at the setup screen.

The issue is only reproducible with this one profile. from the previews investigations I believe the data is not a factor only this profile. I can't determine any differences between profiles to narrow down the issue unfortunately.

Comment 15

[Richard Newman [:rnewman]]

Curiosities:

05-08 10:37:21.962: I/ActivityManager(1359): Process com.android.settings (pid 8253) has died.

Profile migration takes 30 seconds.

After we create the account, a bunch of other system accounts get the chance to run.

Adrian, can you reproduce this if you uncheck every box in your Android "Accounts & sync" screen prior to upgrading? The only thing I can imagine is happening here is that we're waiting for the rest of Android to run.

If you're literally only able to reproduce this with one existing profile, then I'm inclined to close this INCOMPLETE, and say "blame Android"...

Comment 16

[Adrian Tamas (:AdrianT)]

Attachment: logs with only firefox sync active

I have turned off Background data and the profile is still not migrated. However I am no longer seeing the timeout in the logs but I am seeing a keyDispatching timeout in line 914. The interesting issue here is that I get this specific error only with this profile and others work finishing migration.

Comment 17

[Adrian Tamas (:AdrianT)]

Attachment: Logs_Motorola_Droid_pro

I was able to reproduce the issue on a Motorola Droid Pro (Android 2.3.4) but even if all checkboxes were unchecked I am still seeing some Gmail sync attempts. Attaching logs just to be sure.

Comment 18

[Gian-Carlo Pascutto [:gcp]]

Two fixes went in on 2012-05-12 that might have fixed this (bug 750950 and bug 752492). Is it possible to recheck this issue?

Comment 19

[Tony Chung [:tchung]]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #18)
> Two fixes went in on 2012-05-12 that might have fixed this (bug 750950 and
> bug 752492). Is it possible to recheck this issue?

qawanted: Adrian, please retest on a recent nightly.

Comment 20

[Adrian Tamas (:AdrianT)]

Issue is no longer reproducible using Nightly XUL 2012-05-24 and Nightly Native 2012-05-24 on an HTC Desire running Android 2.2. Migration is finished and all data is migrated with the sync account still connected. Marking the issue as WFM