Open Bug 2038290 Opened 2 months ago Updated 2 days ago

Sync broken

Categories

(Firefox for Android :: Accounts and Sync, defect)

Product:
Firefox for Android
Component:
Accounts and Sync
Version:
Firefox 150
Platform:
All
Android
Type:
defect

Tracking

()

Tracking Flags:
Tracking Status
firefox153 --- affected

People

(Reporter: lists, Unassigned)

References

Details

(Whiteboard: [fxdroid][group1])

Attachments

(2 files)

Screenshot_20260508-122746_Firefox.jpg
186.72 KB, image/jpeg
Details
logcatSamsung.txt
785.21 KB, text/plain
Details

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:150.0) Gecko/20100101 Firefox/150.0

Steps to reproduce:

Tap three dots
Tap on account (which shows correct account)
Tap on Sync

Actual results:

Sync now turns grey, hear click, but nothing happens.
Also, all "Choose what to sync" options are checked, but greyed out and cannot alter.
"Sign out" option is shown, so presume logged into account.

Logged out of account
Logged back in via QR code from windows Firefox
Shown on both devices as now paired and logged in

Same results, no sync possible

Also, if I go to the Tabs screen, and tap the "Sync" tab, it is empty, and the "Syncing" swirl appears but nothing ever happens.

Expected results:

Should have synced or shown a reason for the failure

Also, sync is working fine on my account with all my Windoze devices. This is a problem just on my Android phone.

In fact I can happily send a tab from a Windoze browser to my phone and it gets it, and vice-versa.

Sadly it is very tricky to get good logs from Android devices, but it would be fantastic if you were able to follow the instructions at https://wiki.mozilla.org/CloudServices/Sync/File_an_Android_bug and upload the result here, it is likely to be able to tell us what the problem is.

When I went to check it again, it had synced. I did nothing, no phone restart, no restarting Firefox, same network, etc. Syncs fine now. I guess I can try a phone restart and see if the problem crops up again, and if so will try to get a log.

Well it went back to not syncing, exact same behavior as above, but this time it did show as synced couple days ago. This seems to coincide with another bug being fixed (the closed tab message covering the bottom tab in the list) so figure it not working again was triggered by an update (shows 150.0.2). I was going to try to catch a log, but after about an hour it now shows as synced. So looks like some transient issue. Again my laptop etc. were syncing fine at the same time, so does not look like a sync server issues unless something Android client specific.

It sounds like something is just very very slow? Those logcat messages from comment 2 would still be very helpful

I have sameish bug, does this help? keep mind they can send and receive individual tab sent by 'send tab to'
looks sync engine didn't even run after first first fail

05-19 20:57:51.839 21767  8862 I sync_manager::manager: breadcrumb: SyncManager::sync started
05-19 20:57:51.873 21767  8862 I sync_manager::manager: breadcrumb: Checking engines requested (Some { engines: ["history", "bookmarks", "passwords", "tabs", "creditcards"] }) vs local engines (["passwords", "tabs", "bookmarks", "addresses", "creditcards", "history"])
05-19 20:57:51.874 21767  8862 I sync_manager::manager: No backoff in effect (or we decided to ignore it), starting sync
05-19 20:57:51.877 21767  8862 I sync15::client::sync_multiple: Syncing 5 engines
05-19 20:57:51.878 21767  8862 I sync15::client::sync_multiple: Loading/initializing persisted state
05-19 20:57:51.881 21767  8862 I sync15::client::sync_multiple: Preparing client info
05-19 20:57:51.882 21767  8862 I sync15::client::sync_multiple: Entering sync state machine
05-19 20:57:51.882 21767  8862 I sync15::client::sync_multiple: Advancing state machine to ready (full)
05-19 20:57:52.348 21767  8862 I sync15::client::token: Successful fetch of tokenserver token
05-19 20:57:52.754 21767  8862 I sync15::client::storage_client: Successful request to "/1.5/159936400/info/configuration", incoming x-last-modified=ServerTimestamp(0)
05-19 20:58:02.760 21767  8862 W sync15::client::sync_multiple: sync failed: Network error: [no-sentry] Backend error: UnexpectedUniFFICallbackError(reason: "java.net.SocketTimeoutException\n\tat mozilla.components.browser.engine.gecko.fetch.GeckoViewFetchClient.fetch(GeckoViewFetchClient.kt:404)\n\tat mozilla.appservices.httpconfig.FetchBackend.sendRequest(FetchBackend.kt:209)\n\tat mozilla.appservices.viaduct.uniffiCallbackInterfaceBackend$sendRequest$callback$$inlined$uniffiAsyncCallback$1.invokeSuspend(viaduct.kt:101)\n\tat kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:9)\n\tat kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:122)\n\tat kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:127)\n"), final status=NetworkError
05-19 20:58:02.761 21767  8862 I sync_manager::manager: Sync finished with status NetworkError
05-19 20:58:02.773 21767  8862 I sync_manager::manager: breadcrumb: SyncManager sync ended
05-19 21:17:31.291 24073 24073 I FirefoxAccountStateMachine: Sync is enabled
05-19 21:17:31.434 24073 24255 I FirefoxAccount: Registering persistence callback
05-19 21:17:32.503 24073 24107 I FirefoxAccount: Executing: getProfile
05-19 21:17:32.503 24073 24140 I FirefoxAccount: Executing: getProfile
05-19 21:17:33.267 24073 24107 I FirefoxAccount: Successfully executed: getProfile
05-19 21:17:33.269 24073 24140 I FirefoxAccount: Successfully executed: getProfile
05-19 21:17:33.962 24073 24144 I FirefoxAccount: Executing: get attached client
05-19 21:17:34.202 24073 24144 I FirefoxAccount: Successfully executed: get attached client
05-19 21:19:46.740 24073 24073 I FirefoxAccount: Executing: getManageAccountURL
05-19 21:19:47.066 24073 24073 I FirefoxAccount: Successfully executed: getManageAccountURL
05-19 21:19:52.158 26163 26163 I FirefoxAccountStateMachine: Sync is enabled
05-19 21:19:52.255 26163 26346 I FirefoxAccount: Registering persistence callback
05-19 21:19:52.265 26163 26201 I FirefoxAccount: Executing: getProfile
05-19 21:19:52.265 26163 26281 I FirefoxAccount: Executing: getProfile
05-19 21:19:52.268 26163 26281 I FirefoxAccount: Successfully executed: getProfile
05-19 21:19:52.270 26163 26201 I FirefoxAccount: Successfully executed: getProfile
05-19 21:19:55.665 26163 26231 I FirefoxAccount: Executing: get attached client
05-19 21:19:55.956 26163 26231 I FirefoxAccount: Successfully executed: get attached client
05-19 21:23:10.266 27686 27686 I FirefoxAccountStateMachine: Sync is enabled
05-19 21:23:10.436 27686 27868 I FirefoxAccount: Registering persistence callback
05-19 21:23:10.449 27686 27725 I FirefoxAccount: Executing: getProfile
05-19 21:23:10.449 27686 27726 I FirefoxAccount: Executing: getProfile
05-19 21:23:11.991 27686 27725 I FirefoxAccount: Successfully executed: getProfile
05-19 21:23:11.994 27686 27726 I FirefoxAccount: Successfully executed: getProfile
05-19 21:23:14.998 27686 27758 I FirefoxAccount: Executing: get attached client
05-19 21:23:15.207 27686 27758 I FirefoxAccount: Successfully executed: get attached client

Yeah I was thinking this looks like a state error, where something went wrong but some "syncing" flag is still set so another sync is not attempted.

What makes me think this is:

  • In my screenshot above, the sync options are greyed out and clicking "sync now" has no effect, as if it was in progress
  • The tabs "Sync" page is empty with a perpetual swirling "Syncing"

This can go on for hours or days, and then get cleared, not sure how yet, and syncing works.

Thanks for those logs, they helped me reproduce badness on a network error. I suspect the 2 linked bugs will make a big difference here.

See Also: → 2041555, 2041554

The severity field is not set for this bug.
:boek, could you have a look please?

For more information, please visit BugBot documentation.

Flags: needinfo?(jboek)

I have the same issue as OP. The sync status was showing that last sync was completed 8 days ago. I tried fixing the problem by signing out and back in, and that led to the inoperative sync button and grayed out sync items noted by OP.

The problem currently only manifests on my Pixel 9 phone, not on my Samsung tablets. I did have sync problems on my Samsung A9+ tablet about a month ago, which eventually was fixed by reinstalling Firefox.

I'm hoping there'll be a fix so I won't have to reinstall every time.

Funny, right after I posted the preceding comment, I checked again and a sync has now been completed 🤷‍♂️

And now broken again for the last 19 hours on my Pixel phone and 15 hours on my Samsung tablet

This may be coincidence, but it was not syncing for a few days. Today I deleted a bookmark on my laptop (Win10 FF 151.0.4), and an hour later when I checked on my phone it had synced, and would sync again. Could it be some kind of server state issue where a syncing device sets up a new sync needed on the other devices, and that clears the issue? Next time it's not syncing I'll change something on my laptop and see if this is repeatable.

There we go, I finally managed to encounter this bug on Firefox 152.0.1 Android two times in a row.
See also: bug 1924544

First occurrence

Steps to reproduce:

  1. Open Firefox for Android
  2. Navigate around in the browser's user interface (open settings, open the tab switcher, toggle between private browsing mode and normal mode, etc)
  3. Notice that Firefox frequently sends sync requests as I said in bug 2047406 comment 10 (although not always a bookmark sync), this is usually normal
  4. After 2-3 minutes, sync stops working with the following logs, with the "Sync now" button not working due to backoff:
06-21 10:10:32.393 17031 18678 I FxaDeviceConstellation: Refreshing device list...
06-21 10:10:32.393 17031 18678 I FxaDeviceConstellation: Executing: fetching all devices
06-21 10:10:32.394 17031 18678 I FxaDeviceConstellation: Successfully executed: fetching all devices
06-21 10:10:32.394 17031 18678 I FxaDeviceConstellation: Refreshed device list; saw 2 device(s).
06-21 10:10:32.394 17031 18678 I FxaDeviceConstellation: Notifying observer about constellation updates.
06-21 10:10:32.394 17031 18678 I FxaDeviceConstellation: Notifying observer about constellation updates.
06-21 10:10:32.394 17031 18678 I ConstellationObserver: onDevicesUpdate triggered.
06-21 10:10:32.396 17031 17111 I FxaPushSupportFeature: Created a new subscription: onDevicesUpdate: AutoPushSubscription(scope=fxa_push_scope_REDACTED, endpoint=https://updates.push.services.mozilla.com/wpush/v1/REDACTED, publicKey=REDACTED, authKey=REDACTED, appServerKey=)
06-21 10:10:32.400 17031 17031 I LogMiddleware - BrowserStore: mozilla.components.browser.state.action.LastAccessAction$UpdateLastAccessAction
06-21 10:10:32.403 17031 17031 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$MessagingAction$ConsumeMessageToShow
06-21 10:10:32.403 17031 17031 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$MessagingAction$Evaluate
06-21 10:10:32.408 17031 17031 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$UpdateFirstFrameDrawn
06-21 10:10:32.437 17031 18683 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$RecentHistoryChange
06-21 10:10:32.472 17031 18678 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$BookmarksChange
06-21 10:10:32.511 17031 17031 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$CollectionsChange
06-21 10:10:32.512 17031 17031 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$TopSitesChange
06-21 10:10:32.551 17031 17031 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$RecentTabsChange
06-21 10:10:32.592 17031 17031 I LogMiddleware - AppStore: org.mozilla.fenix.components.appstate.AppAction$TopSitesChange
06-21 10:10:32.597 17031 18678 I sync_manager::manager: breadcrumb: SyncManager::sync started
06-21 10:10:32.598 17031 18678 I app-services-error-reporter::breadcrumb: SyncManager::sync started
06-21 10:10:32.613 17031 18678 I sync_manager::manager: breadcrumb: Checking engines requested (Some { engines: ["tabs"] }) vs local engines (["passwords", "tabs", "bookmarks", "addresses", "creditcards", "history"])
06-21 10:10:32.614 17031 18678 I app-services-error-reporter::breadcrumb: Checking engines requested (Some { engines: ["tabs"] }) vs local engines (["passwords", "tabs", "bookmarks", "addresses", "creditcards", "history"])
06-21 10:10:32.615 17031 18678 I sync_manager::manager: No backoff in effect (or we decided to ignore it), starting sync
06-21 10:10:32.615 17031 18678 I sync15::client::sync_multiple: Syncing 1 engines
06-21 10:10:32.615 17031 18678 I sync15::client::sync_multiple: Loading/initializing persisted state
06-21 10:10:32.615 17031 18678 I sync15::client::sync_multiple: Preparing client info
06-21 10:10:32.616 17031 18678 I sync15::client::sync_multiple: Entering sync state machine
06-21 10:10:32.616 17031 18678 I sync15::client::sync_multiple: Advancing state machine to ready (full)
06-21 10:10:32.744 17031 17044 I mozilla.firefo: Background concurrent copying GC freed 194040(8974KB) AllocSpace objects, 15(1892KB) LOS objects, 49% free, 10MB/20MB, paused 133us total 187.209ms
06-21 10:10:33.371 17031 18678 I sync15::client::storage_client: Successful request to "/1.5/SOME_RANDOM_NUMERIC_ID_REDACTED/info/collections", incoming x-last-modified=ServerTimestamp(1782011116860)
06-21 10:10:33.371 17031 18678 I sync15::client::sync_multiple: Synchronizing clients engine
06-21 10:10:33.371 17031 18678 I sync15::clients_engine::engine: Syncing collection clients
06-21 10:10:33.545 17031 17125 I tabs::storage: update_local_state has 1 tab entries
06-21 10:10:33.546 17031 17125 I RemoteTabsStorage: Told the tabs store we have 1
06-21 10:10:33.804 17031 18678 W sync15::client::sync_multiple: sync failed: Network error: [no-sentry] Backend error: UnexpectedUniFFICallbackError(reason: "java.io.IOException: org.mozilla.geckoview.WebRequestError: Request failed, error=0x11, category=0x1\n\tat mozilla.components.browser.engine.gecko.fetch.GeckoViewFetchClient.fetch(GeckoViewFetchClient.kt:398)\n\tat mozilla.appservices.httpconfig.FetchBackend.sendRequest(FetchBackend.kt:209)\n\tat mozilla.appservices.viaduct.uniffiCallbackInterfaceBackend$sendRequest$callback$$inlined$uniffiAsyncCallback$1.invokeSuspend(viaduct.kt:101)\n\tat kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:9)\n\tat kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:121)\n\tat kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:127)\nCaused by: org.mozilla.geckoview.WebRequestError: Request failed, error=0x11, category=0x1\n\tat org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)\n\tat org.mozilla.gecko.GeckoThread.run(GeckoThread.java:926)\n"), final status=NetworkError
06-21 10:10:33.804 17031 18678 I sync_manager::manager: Sync finished with status NetworkError
06-21 10:10:33.804 17031 18678 I sync_manager::manager: breadcrumb: SyncManager sync ended
06-21 10:10:33.804 17031 18678 I app-services-error-reporter::breadcrumb: SyncManager sync ended
06-21 10:10:33.806 17031 18678 E SyncWorker: Network error
06-21 10:10:33.824 17031 17142 I WM-WorkerWrapper: Worker result RETRY for Work [ id=REDACTED, tags={ mozilla.components.service.fxa.sync.WorkManagerSyncWorker,Common,Debounce } ]
06-21 10:10:34.522 17031 17230 I SessionStorage/AutoSave: Save: Periodic
  1. Close the app (including from the recent apps list), and wait for about 5-10 minutes
  2. After reopening the app, sync starts working again (maybe backoff is only about 3 minutes for this occasion, which has passed when waiting for about 5-10 minutes as described above), with the sync logs running as usual from sync_manager::manager: No backoff in effect (or we decided to ignore it), starting sync, until Sync finished with status Ok.

Second occurrence

Steps to reproduce:

  1. Ensure that there are no sync activities currently running in adb logcat.
  2. Close Firefox by pressing the back button. Firefox starts syncing again in the background.
  3. When Firefox is in a syncing state while in background, close Firefox from the recently closed apps list
  4. Notice that from the adb logs, Process [Firefox PID] exited due to signal 9 (Killed) just after sync15::client::sync_multiple: Advancing state machine to ready (full)

Actual results:

  1. When reopening Firefox, it triggers a backoff for about 3 minutes ("Sync now" button can't be clicked)
  2. After waiting for about 3 minutes in the "Account settings" screen, sync starts to retry and work properly again.

Logs when the app is about to be closed:

06-21 10:38:22.374 24058 24977 I sync_manager::manager: breadcrumb: SyncManager::sync started
06-21 10:38:22.378 24058 24977 I app-services-error-reporter::breadcrumb: SyncManager::sync started
06-21 10:38:22.442 24058 24977 I sync_manager::manager: breadcrumb: Checking engines requested (Some { engines: ["tabs"] }) vs local engines (["passwords", "tabs", "bookmarks", "addresses", "creditcards", "history"])
06-21 10:38:22.443 24058 24977 I app-services-error-reporter::breadcrumb: Checking engines requested (Some { engines: ["tabs"] }) vs local engines (["passwords", "tabs", "bookmarks", "addresses", "creditcards", "history"])
06-21 10:38:22.447 24058 24977 I sync_manager::manager: No backoff in effect (or we decided to ignore it), starting sync
06-21 10:38:22.447 24058 24977 I sync15::client::sync_multiple: Syncing 1 engines
06-21 10:38:22.448 24058 24977 I sync15::client::sync_multiple: Loading/initializing persisted state
06-21 10:38:22.449 24058 24977 I sync15::client::sync_multiple: Preparing client info
06-21 10:38:22.449 24058 24977 I sync15::client::sync_multiple: Entering sync state machine
06-21 10:38:22.449 24058 24977 I sync15::client::sync_multiple: Advancing state machine to ready (full)
06-21 10:38:23.110  1887  4530 I Process : PerfMonitor : current process sending signal quiet. PID: 24058 SIG: 9
06-21 10:38:23.334  1887  2086 E libprocessgroup: Failed to kill process cgroup uid 10267 pid 24058 in 221ms, 1 processes remain
06-21 10:38:23.455   621   621 I Zygote  : Process 24058 exited due to signal 9 (Killed)

There were no logs relevant to Firefox Account/Sync when the backoff happens and when the "Sync now" button gets clicked but no sync occurred, except the usual FxaDeviceConstellationand FxaPushSupportFeature stuff.
When the sync did work, it throws the usual normal logs of the sync process, from sync_manager::manager: No backoff in effect (or we decided to ignore it), starting sync, until Sync finished with status Ok.

Severity: -- → S3
Flags: needinfo?(jboek)
Whiteboard: [fxdroid][group1]

A bit more data - it has not synced for a week now, but every day on the account screen it says Syncing and last synced 2 days ago, so that is not updating correctly either.

By the way, as I said in bug 1924544 comment 34, if you really wanted to attempt it to sync, try changing the system time and make sure to return the system time back after it succeeded (usually by setting it back to automatic).

Also, that (the paragraph just above this) could be an opportunity to record logs, so that in case it will also fail, we have more logs to investigate the common cause (for me, I would just output all the system logs, open Firefox, attempt it to sync whether it fails or not, then filter the file by the Firefox PID/sync-related stuff and filtering out any unique identifier/tokens/key, as I described in bug 2047406)

Attached file logcatSamsung.txt —

I just reproduce this issue on Firefox for Android 153.0b6 with a Samsung Galaxy S24 (Android 16).
After scanning the QR code from desktop, the synced tabs tray remained empty, and when going to Account settings, the "Last synchronised: Never" was displayed.

Status: UNCONFIRMED → NEW
QA Whiteboard: [qa-triaged]
status-firefox153: --- → affected
Ever confirmed: true

Attached file logcatSamsung.txt — Details

Did you maybe attach the wrong logcat? I can't see any evidence of Fenix there at all, let alone a sync.

Flags: needinfo?(mlobontiuroman)

Adding up: Or maybe the logcat logs got truncated because of buffer size limitation, that's why I'm dumping it to a file first before running Firefox (and without printing some past logs with adb logcat -T 1) because I experienced that missing logs phenomenon as well before.

Hi Mark, it was the correct logcat, but maybe it got truncated. Sorry. If I encounter this issue again, I'll try to get the logcat with the "sync" evidence.

Flags: needinfo?(mlobontiuroman)

(In reply to E. [:exploraz] from comment #16)

By the way, as I said in bug 1924544 comment 34, if you really wanted to attempt it to sync, try changing the system time and make sure to return the system time back after it succeeded (usually by setting it back to automatic).

Also, that (the paragraph just above this) could be an opportunity to record logs, so that in case it will also fail, we have more logs to investigate the common cause (for me, I would just output all the system logs, open Firefox, attempt it to sync whether it fails or not, then filter the file by the Firefox PID/sync-related stuff and filtering out any unique identifier/tokens/key, as I described in bug 2047406)

I reported in the other thread that the system time trick worked. I want to add that it works...eventually. Just now I had to play with my device and shift the system time, stop Firefox and restart, all several times before it started synching again. It might just mean that there may be a 10-15 minute lag for the synching to restart.

See Also: → 1924544

For bug report tracking: Out of several bug reports I mentioned at bug 2047406 comment 0 (lists two types of bug, with the first point being relevant here), I also noticed that bug 1812111 might be the same bug as this as well, and have additional logs (linked at bug 1924544 comment 25).

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: