Closed Bug 1073693 Opened 11 years ago Closed 11 years ago

Sync doesn't work on Android, fine between desktops

Categories

(Firefox for Android Graveyard :: Android Sync, defect)

Product:
Firefox for Android Graveyard
Component:
Android Sync
Version:
Firefox 32
Platform:
Other
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: Ebeeman, Unassigned)

Details

Attachments

(2 files)

Screen Shot of Android Firefox sync button
35.46 KB, image/png
Details
Screen Shot of Android System Sync
47.13 KB, image/png
Details
User Agent: Mozilla/5.0 (Android; Mobile; rv:32.0) Gecko/32.0 Firefox/32.0 Build ID: 20140923174357 Steps to reproduce: Started with fresh install on Android. Used existing firefox account that had successfully synced between two separate desktops. Sync does not to work. No bookmarks are brought across. I confirmed I was using same Firefox account on the different devices. Actual results: No sync even though it appears to sync when you press the sync button within Android version. Expected results: Desktop bookmarks should appear on Android Firefox application.
Component: General → Android Sync
Product: Firefox for Android → Android Background Services
Are you using the 'new' Sync with a Firefox Account (email/password) or using an old Sync account (where you had to enter a bunch of randomized letters and numbers)? If you are familiar with android ADB, can you attach a log-cat from your device of when you attempt a Sync?
This issue applies to new version of sync. I'll become familiar with Android adb if necessary to produce a log. If there is a recommended user tutorial, please advise. Otherwise, I'll will google to learn. Thanks
09-27 18:39:50.383: I/SBar.NetworkController(614): onDataActivity: direction=3 09-27 18:39:50.383: I/SBar.NetworkController(614): refreshSignalCluster: mobile: mHasMobileDataFeature=true DataTypeShown=zz_moto_stat_sys_data_fully_connected_4g_lte Activity=zz_moto_stat_sys_data_fully_connected_signal_inout Accessibility="4 G L T E" 09-27 18:39:50.696: I/FxAccounts(14719): firefox :: Utils :: Asked to sync 'clients, tabs' and to skip ''. 09-27 18:39:50.704: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage checkPreconditions (org.mozilla.gecko.sync.stage.CheckPreconditionsStage@416e2048)... 09-27 18:39:50.704: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage ensureClusterURL (org.mozilla.gecko.sync.stage.CheckPreconditionsStage@416c57e8)... 09-27 18:39:50.704: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage fetchInfoCollections (org.mozilla.gecko.sync.stage.FetchInfoCollectionsStage@41847c58)... 09-27 18:39:50.719: D/libc(14719): Forward DNS query to netd(h=sync-133-us-west-2.sync.services.mozilla.com s=^) 09-27 18:39:51.563: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage fetchMetaGlobal (org.mozilla.gecko.sync.stage.FetchMetaGlobalStage@4168a200)... 09-27 18:39:51.563: I/FxAccounts(14719): firefox :: FetchMetaGlobalStage :: Trying to use persisted meta/global for this session. 09-27 18:39:51.571: I/FxAccounts(14719): firefox :: FetchMetaGlobalStage :: Using persisted meta/global for this session. 09-27 18:39:51.571: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage ensureKeysStage (org.mozilla.gecko.sync.stage.EnsureCrypto5KeysStage@41840720)... 09-27 18:39:51.594: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage syncClientsEngine (org.mozilla.gecko.sync.stage.SyncClientsEngineStage@4184ec40)... 09-27 18:39:52.094: I/FxAccounts(14719): firefox :: SyncClientsEngineStage :: Local client GUID exists on server and was downloaded. 09-27 18:39:52.157: D/dalvikvm(14719): GC_CONCURRENT freed 1604K, 14% free 10768K/12451K, paused 14ms+6ms, total 61ms 09-27 18:39:52.586: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage syncTabs (org.mozilla.gecko.sync.stage.FennecTabsServerSyncStage@4178df38)... 09-27 18:39:52.594: I/FxAccounts(14719): firefox :: ServerSyncStage :: Skipping stage tabs. 09-27 18:39:52.594: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage syncPasswords (org.mozilla.gecko.sync.stage.PasswordsServerSyncStage@4179ab20)... 09-27 18:39:52.594: I/FxAccounts(14719): firefox :: ServerSyncStage :: Skipping stage passwords. 09-27 18:39:52.594: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage syncBookmarks (org.mozilla.gecko.sync.stage.AndroidBrowserBookmarksServerSyncStage@417adb40)... 09-27 18:39:52.594: I/FxAccounts(14719): firefox :: ServerSyncStage :: Skipping stage bookmarks. 09-27 18:39:52.594: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage syncHistory (org.mozilla.gecko.sync.stage.AndroidBrowserHistoryServerSyncStage@41809f60)... 09-27 18:39:52.602: I/FxAccounts(14719): firefox :: ServerSyncStage :: Skipping stage history. 09-27 18:39:52.602: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage syncFormHistory (org.mozilla.gecko.sync.stage.FormHistoryServerSyncStage@41854f08)... 09-27 18:39:52.602: I/FxAccounts(14719): firefox :: ServerSyncStage :: Skipping stage forms. 09-27 18:39:52.602: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage uploadMetaGlobal (org.mozilla.gecko.sync.stage.UploadMetaGlobalStage@4172fc90)... 09-27 18:39:52.602: I/FxAccounts(14719): firefox :: GlobalSession :: Not uploading updated meta/global record since there are no engines requesting upload. 09-27 18:39:52.602: I/FxAccounts(14719): firefox :: GlobalSession :: Running next stage completed (org.mozilla.gecko.sync.stage.CompletedStage@4168af88)... 09-27 18:39:52.602: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Global session succeeded. 09-27 18:39:52.602: I/FxAccounts(14719): firefox :: FxAccountSchedulePolicy :: Scheduling periodic sync for 43200. 09-27 18:39:53.157: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Sync succeeded. 09-27 18:39:53.157: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Syncing done.
09-27 18:48:55.719: I/FxAccounts(14719): firefox :: FxAccountStatusFragment :: Posting a delayed request for a sync sometime soon. 09-27 18:48:59.266: I/ActivityManager(472): START {flg=0x10000000 cmp=org.mozilla.firefox/org.mozilla.gecko.fxa.activities.FxAccountGetStartedActivity u=0} from pid 14719 09-27 18:48:59.430: I/ActivityManager(472): START {flg=0x10000 cmp=org.mozilla.firefox/org.mozilla.gecko.fxa.activities.FxAccountStatusActivity u=0} from pid 14719 09-27 18:48:59.938: I/ActivityManager(472): Displayed org.mozilla.firefox/org.mozilla.gecko.fxa.activities.FxAccountStatusActivity: +482ms (total +616ms) 09-27 18:49:00.727: I/FxAccounts(14719): firefox :: FxAccountStatusFragment :: Requesting a sync sometime soon. 09-27 18:49:00.743: I/GeckoLogger(14719): firefox :: FxAccountStatusFragment :: Got sync started message; refreshing. 09-27 18:49:00.797: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Syncing FxAccount account named like XXXXXXX@XXXXX.XXX for authority org.mozilla.firefox.db.browser with instance org.mozilla.gecko.fxa.sync.FxAccountSyncAdapter@41856d70. 09-27 18:49:00.821: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Not syncing (background): must wait another 3048075ms. 09-27 18:49:00.836: I/GeckoLogger(14719): firefox :: FxAccountStatusFragment :: Got sync finished message; refreshing. 09-27 18:49:00.977: I/FxAccounts(14719): firefox :: FxAccountStatusFragment :: Persisting engine selections: {history=false, bookmarks=true, tabs=false, passwords=false} 09-27 18:49:01.016: I/FxAccounts(14719): firefox :: FxAccountStatusFragment :: Posting a delayed request for a sync sometime soon. 09-27 18:49:02.094: I/FxAccounts(14719): firefox :: FxAccountStatusFragment :: Persisting engine selections: {history=false, bookmarks=true, tabs=false, passwords=true} 09-27 18:49:02.118: I/FxAccounts(14719): firefox :: FxAccountStatusFragment :: Posting a delayed request for a sync sometime soon. 09-27 18:49:07.118: I/FxAccounts(14719): firefox :: FxAccountStatusFragment :: Requesting a sync sometime soon. 09-27 18:49:07.266: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Syncing FxAccount account named like XXXXXXX@XXXXX.XXX for authority org.mozilla.firefox.db.browser with instance org.mozilla.gecko.fxa.sync.FxAccountSyncAdapter@41856d70. 09-27 18:49:07.383: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Not syncing (background): must wait another 3041515ms. 09-27 18:49:15.540: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Syncing FxAccount account named like XXXXXXX@XXXXX.XXX for authority org.mozilla.firefox.db.browser with instance org.mozilla.gecko.fxa.sync.FxAccountSyncAdapter@41856d70. 09-27 18:49:15.602: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: handleFinal: in Married 09-27 18:49:15.602: I/FxAccounts(14719): firefox :: AndroidFxAccount :: Moving account named like XXXXXXX@XXXXX.XXX to state Married 09-27 18:49:15.719: I/FxAccounts(14719): firefox :: FxAccountNotificationManager :: State Married needs no action; cancelling any existing notification. 09-27 18:49:18.829: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Global session succeeded. 09-27 18:49:18.829: I/FxAccounts(14719): firefox :: FxAccountSchedulePolicy :: Scheduling periodic sync for 43200. 09-27 18:49:18.875: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Sync succeeded. 09-27 18:49:18.875: I/FxAccounts(14719): firefox :: FxAccountSyncAdapter :: Syncing done.
Anything stand out?
Flags: needinfo?(rnewman)
(In reply to Ebeeman from comment #4) > 09-27 18:39:50.696: I/FxAccounts(14719): firefox :: Utils :: Asked to sync > 'clients, tabs' and to skip ''. This sync was triggered from pull-to-refresh. What about going to Android Settings > Accounts & sync > Firefox, menu > Sync now?
Performed sync now both from Android system and from the Firefox sync button. Still no luck getting the bookmarks or the passwords to come over to Android Firefox.
Ebeeman: sorry, I was implying that I need a log during a full sync.
Flags: needinfo?(rnewman)
I will separately post the logs when doing a sync refresh from (1) the android firefox sync button and (2) from the android system. This is first post. It contains the complete log when I perform a sync within android firefox interface itself (see https://bug1073693.bugzilla.mozilla.org/attachment.cgi?id=8497480 for the screenshot): 09-30 08:48:08.711: I/GeckoLogger(11668): firefox :: FirefoxAccounts :: Requesting sync. 09-30 08:48:08.711: I/GeckoLogger(11668): firefox :: FirefoxAccounts :: Sync hints; scheduling now: true; ignoring local rate limit: true; ignoring remote server backoff: true. 09-30 08:48:09.188: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatIntentRcvr 09-30 08:48:09.196: I/SyncStatIntentRcvr(753): Received intent: android.intent.action.SYNC_STATE_CHANGED 09-30 08:48:09.250: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatusService 09-30 08:48:09.250: I/SyncStatusService(753): onStart: android.intent.action.SYNC_STATE_CHANGED 09-30 08:48:09.297: W/BroadcastQueue(473): Permission Denial: receiving Intent { act=android.intent.action.SYNC_STATE_CHANGED flg=0x10 (has extras) } to ProcessRecord{41c25b70 615:com.android.systemui/u0a220} (pid=615, uid=10220) requires com.motorola.blur.service.blur.Permissions.INTERACT_BLUR_SERVICE due to sender com.motorola.blur.service.blur (uid 10055) 09-30 08:48:09.321: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatIntentRcvr 09-30 08:48:09.321: I/SyncStatIntentRcvr(753): Received intent: android.intent.action.SYNC_STATE_CHANGED 09-30 08:48:09.321: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatusService 09-30 08:48:09.321: I/SyncStatusService(753): onStart: android.intent.action.SYNC_STATE_CHANGED 09-30 08:48:09.485: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: Syncing FxAccount account named like XXXXXXX@XXXXX.XXX for authority org.mozilla.firefox.db.browser with instance org.mozilla.gecko.fxa.sync.FxAccountSyncAdapter@4168ba18. 09-30 08:48:09.485: I/FxAccounts(11668): firefox :: FirefoxAccounts :: Sync hints; scheduling now: true; ignoring local rate limit: true; ignoring remote server backoff: true. 09-30 08:48:09.555: I/FxAccounts(11668): firefox :: Utils :: Asked to sync 'clients, tabs' and to skip ''. 09-30 08:48:09.860: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: handleFinal: in Married 09-30 08:48:09.860: I/FxAccounts(11668): firefox :: AndroidFxAccount :: Moving account named like XXXXXXX@XXXXX.XXX to state Married 09-30 08:48:10.360: D/dalvikvm(11668): GC_CONCURRENT freed 1483K, 14% free 9999K/11555K, paused 13ms+24ms, total 227ms 09-30 08:48:10.360: D/dalvikvm(11668): WAIT_FOR_CONCURRENT_GC blocked 69ms 09-30 08:48:10.360: D/dalvikvm(11668): WAIT_FOR_CONCURRENT_GC blocked 66ms 09-30 08:48:10.360: D/dalvikvm(11668): WAIT_FOR_CONCURRENT_GC blocked 49ms 09-30 08:48:10.360: D/dalvikvm(11668): WAIT_FOR_CONCURRENT_GC blocked 66ms 09-30 08:48:10.805: I/FxAccounts(11668): firefox :: FxAccountNotificationManager :: State Married needs no action; cancelling any existing notification. 09-30 08:48:10.867: I/ActivityManager(473): Process com.facebook.katana (pid 11299) has died. 09-30 08:48:10.930: I/ActivityManager(473): Process com.google.android.youtube (pid 11372) has died. 09-30 08:48:10.953: D/ModemStatsService(11614): onDataActivity 09-30 08:48:10.953: D/ModemStatsService(11614): direction is 3 09-30 08:48:10.961: D/MotoSystemUIUtils(615): Not on network extender 09-30 08:48:10.961: I/SBar.NetworkController(615): onDataActivity: direction=3 09-30 08:48:10.985: D/GeckoTabs(11668): handleMessage: DOMTitleChanged 09-30 08:48:10.992: D/ModemStatsService(11614): Idle_Duration=725 09-30 08:48:10.992: I/SBar.NetworkController(615): refreshSignalCluster: mobile: mHasMobileDataFeature=true DataTypeShown=zz_moto_stat_sys_data_fully_connected_4g_lte Activity=zz_moto_stat_sys_data_fully_connected_signal_inout Accessibility="4 G L T E" 09-30 08:48:11.110: I/ActivityManager(473): Process com.motorola.messaging (pid 8693) has died. 09-30 08:48:12.969: D/ModemStatsService(11614): onDataActivity 09-30 08:48:12.969: D/ModemStatsService(11614): direction is 2 09-30 08:48:12.969: D/MotoSystemUIUtils(615): Not on network extender 09-30 08:48:12.969: I/SBar.NetworkController(615): onDataActivity: direction=2 09-30 08:48:12.985: I/SBar.NetworkController(615): refreshSignalCluster: mobile: mHasMobileDataFeature=true DataTypeShown=zz_moto_stat_sys_data_fully_connected_4g_lte Activity=zz_moto_stat_sys_data_fully_connected_signal_out Accessibility="4 G L T E" 09-30 08:48:13.391: I/Choreographer(11668): Skipped 93 frames! The application may be doing too much work on its main thread. 09-30 08:48:13.539: D/GeckoTabs(11668): handleMessage: Content:PageShow 09-30 08:48:13.539: D/libc(11668): Forward DNS query to netd(h=token.services.mozilla.com s=^) 09-30 08:48:13.547: D/GeckoToolbar(11668): onTabChanged: PAGE_SHOW 09-30 08:48:13.547: D/GeckoBrowserApp(11668): BrowserApp.onTabChanged: 5: PAGE_SHOW 09-30 08:48:14.000: D/ModemStatsService(11614): onDataActivity 09-30 08:48:14.000: D/ModemStatsService(11614): direction is 3 09-30 08:48:14.000: D/MotoSystemUIUtils(615): Not on network extender 09-30 08:48:14.000: I/SBar.NetworkController(615): onDataActivity: direction=3 09-30 08:48:14.008: I/SBar.NetworkController(615): refreshSignalCluster: mobile: mHasMobileDataFeature=true DataTypeShown=zz_moto_stat_sys_data_fully_connected_4g_lte Activity=zz_moto_stat_sys_data_fully_connected_signal_inout Accessibility="4 G L T E" 09-30 08:48:14.086: I/Choreographer(11668): Skipped 32 frames! The application may be doing too much work on its main thread. 09-30 08:48:14.657: D/GeckoTabs(11668): handleMessage: Content:StateChange 09-30 08:48:14.664: D/GeckoToolbar(11668): onTabChanged: STOP 09-30 08:48:14.696: D/FaviconCache(11668): Favicon cache fullness: 1024/524288 09-30 08:48:14.703: I/GeckoToolbarDisplayLayout(11668): zerdatime 104869118 - Throbber stop 09-30 08:48:14.836: D/GeckoBrowserApp(11668): BrowserApp.onTabChanged: 5: STOP 09-30 08:48:14.938: D/GeckoToolbar(11668): onTabChanged: FAVICON 09-30 08:48:14.946: D/GeckoToolbarDisplayLayout(11668): updateFavicon(android.graphics.Bitmap@41895af0) 09-30 08:48:14.946: D/GeckoBrowserApp(11668): BrowserApp.onTabChanged: 5: FAVICON 09-30 08:48:15.430: D/GeckoThumbnailHelper(11668): Using new thumbnail size: 131520 (width 240) 09-30 08:48:15.430: D/GeckoThumbnailHelper(11668): Sending thumbnail event: 240, 137 09-30 08:48:15.430: D/GeckoThumbnailHelper(11668): Using new thumbnail size: 131520 (width 240) 09-30 08:48:15.430: D/GeckoThumbnailHelper(11668): Sending thumbnail event: 240, 137 09-30 08:48:15.430: D/GeckoThumbnailHelper(11668): Using new thumbnail size: 131520 (width 240) 09-30 08:48:15.430: D/GeckoThumbnailHelper(11668): Sending thumbnail event: 240, 137 09-30 08:48:15.438: D/GeckoThumbnailHelper(11668): Using new thumbnail size: 131520 (width 240) 09-30 08:48:15.438: D/GeckoThumbnailHelper(11668): Sending thumbnail event: 240, 137 09-30 08:48:15.438: D/MotoSystemUIUtils(615): Not on network extender 09-30 08:48:15.438: D/ModemStatsService(11614): onSignalStrengthsChanged 09-30 08:48:15.438: I/SBar.NetworkController(615): onSignalStrengthsChanged SignalStrength: 99 -1 -91 -70 -91 -1 5 7 -105 -7 156 9 cdma 0 -108 -1 false 0 0 3 2 3 2 2 99 5 5 5 5 5 5 5 99 level=3 09-30 08:48:15.446: D/ModemStatsService(11614): CDMA, mRssi=-91, mEcio=-70 09-30 08:48:15.453: I/SBar.NetworkController(615): refreshSignalCluster: mobile: Signal=zz_moto_stat_sys_signal_5bar_3_fully Roaming=(none) mSimIconId=(none) Accessibility="Phone three bars.","Not roaming.","" 09-30 08:48:15.492: D/GeckoThumbnailHelper(11668): handleThumbnailData: 131520 09-30 08:48:16.930: D/GeckoToolbar(11668): onTabChanged: THUMBNAIL 09-30 08:48:16.930: D/GeckoBrowserApp(11668): BrowserApp.onTabChanged: 5: THUMBNAIL 09-30 08:48:17.016: D/ModemStatsService(11614): onDataActivity 09-30 08:48:17.016: D/ModemStatsService(11614): direction is 2 09-30 08:48:17.039: D/MotoSystemUIUtils(615): Not on network extender 09-30 08:48:17.039: I/SBar.NetworkController(615): onDataActivity: direction=2 09-30 08:48:17.047: I/SBar.NetworkController(615): refreshSignalCluster: mobile: mHasMobileDataFeature=true DataTypeShown=zz_moto_stat_sys_data_fully_connected_4g_lte Activity=zz_moto_stat_sys_data_fully_connected_signal_out Accessibility="4 G L T E" 09-30 08:48:17.938: I/FxAccounts(11668): firefox :: Utils :: Asked to sync 'clients, tabs' and to skip ''. 09-30 08:48:17.985: D/dalvikvm(11668): GC_CONCURRENT freed 1695K, 15% free 10170K/11939K, paused 17ms+4ms, total 63ms 09-30 08:48:17.985: D/dalvikvm(11668): WAIT_FOR_CONCURRENT_GC blocked 31ms 09-30 08:48:17.992: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage checkPreconditions (org.mozilla.gecko.sync.stage.CheckPreconditionsStage@41a2b920)... 09-30 08:48:17.992: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage ensureClusterURL (org.mozilla.gecko.sync.stage.CheckPreconditionsStage@41a2f0e0)... 09-30 08:48:17.992: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage fetchInfoCollections (org.mozilla.gecko.sync.stage.FetchInfoCollectionsStage@41a2bfd0)... 09-30 08:48:18.000: D/libc(11668): Forward DNS query to netd(h=sync-133-us-west-2.sync.services.mozilla.com s=^) 09-30 08:48:18.024: D/ModemStatsService(11614): onDataActivity 09-30 08:48:18.024: D/MotoSystemUIUtils(615): Not on network extender 09-30 08:48:18.024: I/SBar.NetworkController(615): onDataActivity: direction=3 09-30 08:48:18.032: D/ModemStatsService(11614): direction is 3 09-30 08:48:18.032: I/SBar.NetworkController(615): refreshSignalCluster: mobile: mHasMobileDataFeature=true DataTypeShown=zz_moto_stat_sys_data_fully_connected_4g_lte Activity=zz_moto_stat_sys_data_fully_connected_signal_inout Accessibility="4 G L T E" 09-30 08:48:18.844: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage fetchMetaGlobal (org.mozilla.gecko.sync.stage.FetchMetaGlobalStage@41a2c2a0)... 09-30 08:48:18.852: I/FxAccounts(11668): firefox :: FetchMetaGlobalStage :: Trying to use persisted meta/global for this session. 09-30 08:48:18.860: I/FxAccounts(11668): firefox :: FetchMetaGlobalStage :: Using persisted meta/global for this session. 09-30 08:48:18.860: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage ensureKeysStage (org.mozilla.gecko.sync.stage.EnsureCrypto5KeysStage@41a2c860)... 09-30 08:48:18.907: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncClientsEngine (org.mozilla.gecko.sync.stage.SyncClientsEngineStage@41a2cb78)... 09-30 08:48:19.219: I/FxAccounts(11668): firefox :: SyncClientsEngineStage :: Local client GUID exists on server and was downloaded. 09-30 08:48:19.313: D/dalvikvm(11668): GC_FOR_ALLOC freed 1101K, 16% free 10301K/12131K, paused 43ms, total 43ms 09-30 08:48:19.430: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncTabs (org.mozilla.gecko.sync.stage.FennecTabsServerSyncStage@41a2da40)... 09-30 08:48:19.438: I/FxAccounts(11668): firefox :: ServerSyncStage :: Skipping stage tabs. 09-30 08:48:19.438: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncPasswords (org.mozilla.gecko.sync.stage.PasswordsServerSyncStage@41a2dd38)... 09-30 08:48:19.438: I/FxAccounts(11668): firefox :: ServerSyncStage :: Skipping stage passwords. 09-30 08:48:19.438: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncBookmarks (org.mozilla.gecko.sync.stage.AndroidBrowserBookmarksServerSyncStage@41a2e128)... 09-30 08:48:19.438: I/FxAccounts(11668): firefox :: ServerSyncStage :: Skipping stage bookmarks. 09-30 08:48:19.446: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncHistory (org.mozilla.gecko.sync.stage.AndroidBrowserHistoryServerSyncStage@41a2e450)... 09-30 08:48:19.446: I/FxAccounts(11668): firefox :: ServerSyncStage :: Skipping stage history. 09-30 08:48:19.453: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncFormHistory (org.mozilla.gecko.sync.stage.FormHistoryServerSyncStage@41a2e758)... 09-30 08:48:19.453: I/FxAccounts(11668): firefox :: ServerSyncStage :: Skipping stage forms. 09-30 08:48:19.453: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage uploadMetaGlobal (org.mozilla.gecko.sync.stage.UploadMetaGlobalStage@41a2ea40)... 09-30 08:48:19.453: I/FxAccounts(11668): firefox :: GlobalSession :: Not uploading updated meta/global record since there are no engines requesting upload. 09-30 08:48:19.453: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage completed (org.mozilla.gecko.sync.stage.CompletedStage@41a2ed00)... 09-30 08:48:19.453: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: Global session succeeded. 09-30 08:48:19.453: I/FxAccounts(11668): firefox :: FxAccountSchedulePolicy :: Scheduling periodic sync for 43200. 09-30 08:48:19.524: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: Sync succeeded. 09-30 08:48:19.524: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: Syncing done. 09-30 08:48:19.586: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatIntentRcvr 09-30 08:48:19.586: I/SyncStatIntentRcvr(753): Received intent: android.intent.action.SYNC_STATE_CHANGED 09-30 08:48:19.594: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatusService 09-30 08:48:19.594: I/SyncStatusService(753): onStart: android.intent.action.SYNC_STATE_CHANGED 09-30 08:48:19.602: W/BroadcastQueue(473): Permission Denial: receiving Intent { act=android.intent.action.SYNC_STATE_CHANGED flg=0x10 (has extras) } to ProcessRecord{41c25b70 615:com.android.systemui/u0a220} (pid=615, uid=10220) requires com.motorola.blur.service.blur.Permissions.INTERACT_BLUR_SERVICE due to sender com.motorola.blur.service.blur (uid 10055) 09-30 08:48:19.617: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatIntentRcvr 09-30 08:48:19.617: I/SyncStatIntentRcvr(753): Received intent: android.intent.action.SYNC_STATE_CHANGED 09-30 08:48:19.617: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatusService 09-30 08:48:19.617: I/SyncStatusService(753): onStart: android.intent.action.SYNC_STATE_CHANGED
The is second post with the complete log following a sync refresh done from the Android System sync button. The second attachment has a screen shot pic where the android system sync is initiated. Of particular note is the point in log at "09-30 09:12:40.172: W/FxAccounts(11668): firefox :: CountCheckingServer11RepositorySession :: Too many items to sync safely. Skipping." ... then later "Session requested skip. Short-circuiting sync." It seems the code sees 5482 items to be synced but skips them for some reason. For passwords just a bit earlier in log, it also doesn't send over the data 09-30 09:12:39.805: I/FxAccounts(11668): firefox :: ServerSyncStage :: Stage passwords received 0 and sent 0 records in 0.44 seconds. Here is log itself: >>>>>>>>> 09-30 09:12:36.367: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: Syncing FxAccount account named like XXXXXXX@XXXXX.XXX for authority org.mozilla.firefox.db.browser with instance org.mozilla.gecko.fxa.sync.FxAccountSyncAdapter@4168ba18. 09-30 09:12:36.367: I/FxAccounts(11668): firefox :: FirefoxAccounts :: Sync hints; scheduling now: true; ignoring local rate limit: true; ignoring remote server backoff: true. 09-30 09:12:36.399: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatIntentRcvr 09-30 09:12:36.399: I/SyncStatIntentRcvr(753): Received intent: android.intent.action.SYNC_STATE_CHANGED 09-30 09:12:36.407: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatusService 09-30 09:12:36.407: I/SyncStatusService(753): onStart: android.intent.action.SYNC_STATE_CHANGED 09-30 09:12:36.414: W/BroadcastQueue(473): Permission Denial: receiving Intent { act=android.intent.action.SYNC_STATE_CHANGED flg=0x10 (has extras) } to ProcessRecord{41c25b70 615:com.android.systemui/u0a220} (pid=615, uid=10220) requires com.motorola.blur.service.blur.Permissions.INTERACT_BLUR_SERVICE due to sender com.motorola.blur.service.blur (uid 10055) 09-30 09:12:36.430: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatIntentRcvr 09-30 09:12:36.430: I/SyncStatIntentRcvr(753): Received intent: android.intent.action.SYNC_STATE_CHANGED 09-30 09:12:36.430: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatusService 09-30 09:12:36.438: I/SyncStatusService(753): onStart: android.intent.action.SYNC_STATE_CHANGED 09-30 09:12:36.469: W/InputMethodManagerService(473): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@41918070 attribute=null 09-30 09:12:36.469: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: handleFinal: in Married 09-30 09:12:36.469: I/FxAccounts(11668): firefox :: AndroidFxAccount :: Moving account named like XXXXXXX@XXXXX.XXX to state Married 09-30 09:12:36.524: D/BackupManagerService(473): Now staging backup of android 09-30 09:12:36.571: I/FxAccounts(11668): firefox :: FxAccountNotificationManager :: State Married needs no action; cancelling any existing notification. 09-30 09:12:36.586: D/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(11668): Connection closed 09-30 09:12:36.586: D/class ch.boye.httpclientandroidlib.impl.client.DefaultHttpClient(11668): Closing the connection. 09-30 09:12:36.586: D/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(11668): Connection closed 09-30 09:12:36.586: I/class ch.boye.httpclientandroidlib.impl.client.DefaultHttpClient(11668): Retrying request 09-30 09:12:36.586: D/class ch.boye.httpclientandroidlib.impl.client.DefaultHttpClient(11668): Reopening the direct connection. 09-30 09:12:36.586: D/libc(11668): Forward DNS query to netd(h=token.services.mozilla.com s=^) 09-30 09:12:37.328: D/MotoSystemUIUtils(615): Not on network extender 09-30 09:12:37.328: I/SBar.NetworkController(615): onDataActivity: direction=3 09-30 09:12:37.328: D/ModemStatsService(11614): onDataActivity 09-30 09:12:37.328: D/ModemStatsService(11614): direction is 3 09-30 09:12:37.328: I/SBar.NetworkController(615): refreshSignalCluster: mobile: mHasMobileDataFeature=true DataTypeShown=zz_moto_stat_sys_data_fully_connected_4g_lte Activity=zz_moto_stat_sys_data_fully_connected_signal_inout Accessibility="4 G L T E" 09-30 09:12:37.336: D/ModemStatsService(11614): Idle_Duration=1978 09-30 09:12:37.750: D/dalvikvm(11668): GC_CONCURRENT freed 1736K, 17% free 10983K/13091K, paused 3ms+17ms, total 88ms 09-30 09:12:37.969: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage checkPreconditions (org.mozilla.gecko.sync.stage.CheckPreconditionsStage@417afa90)... 09-30 09:12:37.969: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage ensureClusterURL (org.mozilla.gecko.sync.stage.CheckPreconditionsStage@4171f580)... 09-30 09:12:37.969: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage fetchInfoCollections (org.mozilla.gecko.sync.stage.FetchInfoCollectionsStage@417aecd8)... 09-30 09:12:37.977: D/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(11668): Connection closed 09-30 09:12:37.977: D/class ch.boye.httpclientandroidlib.impl.client.DefaultHttpClient(11668): Closing the connection. 09-30 09:12:37.985: D/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(11668): Connection closed 09-30 09:12:37.985: I/class ch.boye.httpclientandroidlib.impl.client.DefaultHttpClient(11668): Retrying request 09-30 09:12:37.985: D/class ch.boye.httpclientandroidlib.impl.client.DefaultHttpClient(11668): Reopening the direct connection. 09-30 09:12:37.985: D/libc(11668): Forward DNS query to netd(h=sync-133-us-west-2.sync.services.mozilla.com s=^) 09-30 09:12:38.758: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage fetchMetaGlobal (org.mozilla.gecko.sync.stage.FetchMetaGlobalStage@417ae910)... 09-30 09:12:38.758: I/FxAccounts(11668): firefox :: FetchMetaGlobalStage :: Trying to use persisted meta/global for this session. 09-30 09:12:38.774: I/FxAccounts(11668): firefox :: FetchMetaGlobalStage :: Using persisted meta/global for this session. 09-30 09:12:38.774: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage ensureKeysStage (org.mozilla.gecko.sync.stage.EnsureCrypto5KeysStage@417a9d18)... 09-30 09:12:38.789: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncClientsEngine (org.mozilla.gecko.sync.stage.SyncClientsEngineStage@41a84800)... 09-30 09:12:39.039: I/dalvikvm(11668): Total arena pages for JIT: 11 09-30 09:12:39.039: I/dalvikvm(11668): Total arena pages for JIT: 12 09-30 09:12:39.039: I/dalvikvm(11668): Total arena pages for JIT: 13 09-30 09:12:39.039: I/dalvikvm(11668): Total arena pages for JIT: 14 09-30 09:12:39.039: I/FxAccounts(11668): firefox :: SyncClientsEngineStage :: Local client GUID exists on server and was downloaded. 09-30 09:12:39.047: I/dalvikvm(11668): Total arena pages for JIT: 15 09-30 09:12:39.047: I/dalvikvm(11668): Total arena pages for JIT: 16 09-30 09:12:39.047: I/dalvikvm(11668): Total arena pages for JIT: 17 09-30 09:12:39.086: I/dalvikvm(11668): Total arena pages for JIT: 18 09-30 09:12:39.242: D/dalvikvm(11668): GC_CONCURRENT freed 1622K, 16% free 11100K/13091K, paused 6ms+9ms, total 68ms 09-30 09:12:39.242: D/dalvikvm(11668): WAIT_FOR_CONCURRENT_GC blocked 60ms 09-30 09:12:39.328: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncTabs (org.mozilla.gecko.sync.stage.FennecTabsServerSyncStage@41a84868)... 09-30 09:12:39.336: I/FxAccounts(11668): firefox :: ServerSyncStage :: Skipping stage tabs. 09-30 09:12:39.336: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncPasswords (org.mozilla.gecko.sync.stage.PasswordsServerSyncStage@41a848b0)... 09-30 09:12:39.383: I/ActivityManager(473): Start proc org.mozilla.firefox.PasswordsProvider for content provider org.mozilla.firefox/org.mozilla.gecko.db.PasswordsProvider: pid=12117 uid=10122 gids={3003, 1015, 1006, 1028} 09-30 09:12:39.407: E/Trace(12117): error opening trace file: No such file or directory (2) 09-30 09:12:39.407: I/ActivityManager(473): No longer want com.google.android.apps.maps (pid 11580): hidden #21 09-30 09:12:39.422: W/ActivityManager(473): Scheduling restart of crashed service com.google.android.apps.maps/com.google.googlenav.prefetch.android.PrefetcherService in 5000ms 09-30 09:12:39.539: I/ActivityThread(12117): Pub org.mozilla.firefox.db.passwords: org.mozilla.gecko.db.PasswordsProvider 09-30 09:12:39.539: D/dalvikvm(12117): Trying to load lib /data/data/org.mozilla.firefox/lib/libmozglue.so 0x416986b0 09-30 09:12:39.547: D/dalvikvm(12117): Added shared lib /data/data/org.mozilla.firefox/lib/libmozglue.so 0x416986b0 09-30 09:12:39.547: D/dalvikvm(12117): No JNI_OnLoad found in /data/data/org.mozilla.firefox/lib/libmozglue.so 0x416986b0, skipping init 09-30 09:12:39.555: D/dalvikvm(12117): Trying to load lib /data/data/org.mozilla.firefox/lib/libmozglue.so 0x416986b0 09-30 09:12:39.555: D/dalvikvm(12117): Shared lib '/data/data/org.mozilla.firefox/lib/libmozglue.so' already loaded in same CL 0x416986b0 09-30 09:12:39.555: I/FxAccounts(11668): firefox :: RecordsChannel :: No data available: short-circuiting flow from source org.mozilla.gecko.sync.middleware.Crypto5MiddlewareRepositorySession@416916f0 09-30 09:12:39.571: D/GeckoProfile(12117): Found profile dir. 09-30 09:12:39.571: E/GeckoLibLoad(12117): Load sqlite start 09-30 09:12:39.625: E/GeckoLinker(12117): /data/app/org.mozilla.firefox-1.apk!/assets/libnss3.so: Warning: unhandled flags #8 not handled 09-30 09:12:39.664: E/GeckoLibLoad(12117): Load sqlite done 09-30 09:12:39.664: E/GeckoLibLoad(12117): Load nss start 09-30 09:12:39.664: E/GeckoLibLoad(12117): Load nss done 09-30 09:12:39.742: D/SQLiteBridge(12117): Journal mode: wal 09-30 09:12:39.805: I/FxAccounts(11668): firefox :: ServerSyncStage :: Stage passwords received 0 and sent 0 records in 0.44 seconds. 09-30 09:12:39.805: I/FxAccounts(11668): firefox :: ServerSyncStage :: Advancing session. 09-30 09:12:39.805: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncBookmarks (org.mozilla.gecko.sync.stage.AndroidBrowserBookmarksServerSyncStage@41a848f8)... 09-30 09:12:39.813: I/FxAccounts(11668): firefox :: CountCheckingServer11RepositorySession :: Collection bookmarks is starting a first sync; checking counts. 09-30 09:12:40.172: I/FxAccounts(11668): firefox :: CountCheckingServer11RepositorySession :: First sync for bookmarks: 5482 items. 09-30 09:12:40.172: W/FxAccounts(11668): firefox :: CountCheckingServer11RepositorySession :: Too many items to sync safely. Skipping. 09-30 09:12:40.180: I/FxAccounts(11668): firefox :: SynchronizerSession :: Session requested skip. Short-circuiting sync. 09-30 09:12:40.188: I/FxAccounts(11668): firefox :: ServerSyncStage :: Stage bookmarks received -1 and sent -1 records in 0.38 seconds. 09-30 09:12:40.188: I/FxAccounts(11668): firefox :: ServerSyncStage :: Advancing session. 09-30 09:12:40.188: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncHistory (org.mozilla.gecko.sync.stage.AndroidBrowserHistoryServerSyncStage@41a84940)... 09-30 09:12:40.188: I/FxAccounts(11668): firefox :: ServerSyncStage :: Skipping stage history. 09-30 09:12:40.188: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage syncFormHistory (org.mozilla.gecko.sync.stage.FormHistoryServerSyncStage@41a84988)... 09-30 09:12:40.188: I/FxAccounts(11668): firefox :: ServerSyncStage :: Skipping stage forms. 09-30 09:12:40.188: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage uploadMetaGlobal (org.mozilla.gecko.sync.stage.UploadMetaGlobalStage@417866a8)... 09-30 09:12:40.196: I/FxAccounts(11668): firefox :: GlobalSession :: Not uploading updated meta/global record since there are no engines requesting upload. 09-30 09:12:40.196: I/FxAccounts(11668): firefox :: GlobalSession :: Running next stage completed (org.mozilla.gecko.sync.stage.CompletedStage@4177e900)... 09-30 09:12:40.196: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: Global session succeeded. 09-30 09:12:40.196: I/FxAccounts(11668): firefox :: FxAccountSchedulePolicy :: Scheduling periodic sync for 43200. 09-30 09:12:40.235: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: Sync succeeded. 09-30 09:12:40.235: I/FxAccounts(11668): firefox :: FxAccountSyncAdapter :: Syncing done. 09-30 09:12:40.274: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatIntentRcvr 09-30 09:12:40.274: I/SyncStatIntentRcvr(753): Received intent: android.intent.action.SYNC_STATE_CHANGED 09-30 09:12:40.282: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatusService 09-30 09:12:40.282: I/SyncStatusService(753): onStart: android.intent.action.SYNC_STATE_CHANGED 09-30 09:12:40.297: W/BroadcastQueue(473): Permission Denial: receiving Intent { act=android.intent.action.SYNC_STATE_CHANGED flg=0x10 (has extras) } to ProcessRecord{41c25b70 615:com.android.systemui/u0a220} (pid=615, uid=10220) requires com.motorola.blur.service.blur.Permissions.INTERACT_BLUR_SERVICE due to sender com.motorola.blur.service.blur (uid 10055) 09-30 09:12:40.321: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatIntentRcvr 09-30 09:12:40.321: I/SyncStatIntentRcvr(753): Received intent: android.intent.action.SYNC_STATE_CHANGED 09-30 09:12:40.328: D/CheckinProvider(473): insertEvents Process tag not allowed: SyncStatusService 09-30 09:12:40.328: I/SyncStatusService(753): onStart: android.intent.action.SYNC_STATE_CHANGED
Just double checked and confirmed the password sync performed properly to android. I implied in my last post that zero passwords had synced and this is not true. It is only the bookmarks that are not coming over during the sync.
> First sync for bookmarks: 5482 items. > Too many items to sync safely. Skipping. > Session requested skip. Short-circuiting sync. > Stage bookmarks received -1 and sent -1 records in 0.38 seconds.
Yup, you're hitting a safety valve, so this is actually working as intended. Bookmark sync isn't (currently) sophisticated enough to deal with Android interruptions, network issues, and other random acts of horror. The probability of tripping up approaches 1 as the number of bookmarks increases. In Bug 814331 we put a cap at 5000, because too many users were having issues above that. You have two choices right now: * Don't sync your bookmarks to your Android device. You can use a service like Pinboard.in instead of local bookmarks. * Delete 482 bookmarks and folders to bring the number below the cap. Make sure you're on wifi when you sync! At some point in the future this limitation will be removed, but I can't promise when.
Status: UNCONFIRMED → RESOLVED
Closed: 11 years ago
Resolution: --- → WORKSFORME
Strange that the PC version didn't run into this limitation too...my cell phone serves as my internet service provider for both itself and my PC's. Maybe there were some network interruptions there on PC side as well and I just didn't realize it. thanks for looking into this issue. Hopefully adding code to deal with network latency/interruptions when syncing is on the future enhancement list.
(In reply to Ebeeman from comment #17) > Strange that the PC version didn't run into this limitation too... The codebase is completely different between the two. Desktop certainly has its own bugs, but typically connections are faster and desktop doesn't suffer under Android's limitations, so limiting bookmark size wouldn't really help. > thanks for looking into this issue. Hopefully adding code to deal with > network latency/interruptions when syncing is on the future enhancement list. There are bugs on file -- e.g., Bug 814801.
Product: Android Background Services → Firefox for Android
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: