1666896917333 FirefoxAccounts DEBUG Notifying observers of fxaccounts:on_pre_logout 1666896917334 FirefoxAccounts DEBUG removing account data 1666896917334 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1666896917334 FirefoxAccounts TRACE starting write of json user data: null 1666896917335 FirefoxAccounts INFO An accountState promise was resolved, but was actually rejected due to a different user being signed in. Originally resolved with: {"email":"ingo@mydomain.de","uid":"0c833923111145c59aa98328e6f5201a","verified":true,"displayName":"Ingo","avatar":"https://firefoxusercontent.com/xxxx","avatarDefault":false} 1666896917336 FirefoxAccounts INFO An accountState promise was rejected, but we are ignoring that reason and rejecting it due to a different user being signed in. Originally rejected with: Error: Another user has signed in(resource://gre/modules/FxAccounts.jsm:187:29) JS Stack trace: getUserAccountData@FxAccounts.jsm:187:29 getSignedInUser/<@FxAccounts.jsm:546:39 withCurrentAccountState@FxAccounts.jsm:761:22 _withCurrentAccountState@FxAccounts.jsm:426:27 getSignedInUser@FxAccounts.jsm:545:17 _getFxaSignedInUser@TelemetryEnvironment.jsm:1779:28 _updateServicesInfo@TelemetryEnvironment.jsm:1794:31 observe@TelemetryEnvironment.jsm:1430:14 notifyStateUpdated@UIState.jsm:140:18 refreshState@UIState.jsm:127:10 1666896917354 FirefoxAccounts TRACE finished write of json user data - took: 20 1666896917357 FirefoxAccounts TRACE storage set finished clearing account data 1666896917357 FirefoxAccounts DEBUG account data reset 1666896917357 FirefoxAccounts TRACE StorageManager finalizing 1666896917357 FirefoxAccounts TRACE StorageManager finalized 1666896917357 FirefoxAccounts TRACE initializing new storage manager 1666896917357 FirefoxAccounts TRACE starting fetch of json user data 1666896917358 FirefoxAccounts TRACE finished fetch of json user data - took: 1 1666896917358 FirefoxAccounts TRACE initializing of new storage manager done 1666896917358 FirefoxAccounts DEBUG Notifying observers of fxaccounts:onlogout 1666896917358 Sync.SyncAuthManager DEBUG observed fxaccounts:onlogout 1666896917358 Sync.SyncAuthManager INFO Sync is not configured, so ignoring the notification 1666896917358 FirefoxAccounts DEBUG Unsubscribing from FxA push. 1666896917359 FirefoxAccounts DEBUG FxAccountsPush loading service 1666896917359 FirefoxAccounts DEBUG FxAccountsPush initialized 1666896917359 FirefoxAccounts TRACE FxAccountsPushService unsubscribe 1666896917361 Sync.LogManager DEBUG Done deleting files. 1666896917558 FirefoxAccounts DEBUG FxAccountsPushService unsubscribed 1666896917558 FirefoxAccounts DEBUG Destroying session and device. 1666896917559 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/session/destroy?service=sync 1666896917559 Services.Common.RESTRequest DEBUG POST Length: 2 1666896918369 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/session/destroy?service=sync 200 1666896918369 Hawk DEBUG (Response) /session/destroy?service=sync: code: 200 - Status text: OK 1666896918369 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -369 1666896918369 FirefoxAccounts DEBUG Destroying all OAuth tokens. 1666896918370 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/destroy 1666896918370 Services.Common.RESTRequest DEBUG POST Length: 900 1666896918370 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/destroy 1666896918370 Services.Common.RESTRequest DEBUG POST Length: 969 1666896918562 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/destroy 200 1666896918562 Hawk DEBUG (Response) /oauth/destroy: code: 200 - Status text: OK 1666896918562 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -562 1666896919136 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/destroy 200 1666896919136 Hawk DEBUG (Response) /oauth/destroy: code: 200 - Status text: OK 1666896919136 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -136 1666896919136 FirefoxAccounts DEBUG Notifying observers of testhelper-fxa-signout-complete 1666896922464 FirefoxAccounts DEBUG FxAccountsWebChannel message received: fxaccounts:fxa_status 1666896922464 FirefoxAccounts DEBUG fxa_status received 1666896922464 FirefoxAccounts DEBUG service: sync 1666896922464 FirefoxAccounts DEBUG is private browsing: false 1666896923264 FirefoxAccounts DEBUG FxAccountsWebChannel message received: fxaccounts:loaded 1666896923264 FirefoxAccounts WARN Unrecognized FxAccountsWebChannel command: fxaccounts:loaded 1666896930121 FirefoxAccounts DEBUG FxAccountsWebChannel message received: fxaccounts:can_link_account 1666896930121 FirefoxAccounts DEBUG FxAccountsWebChannel response: {"command":"fxaccounts:can_link_account","messageId":"16668969301202","data":{"ok":true}} 1666896949413 FirefoxAccounts DEBUG FxAccountsWebChannel message received: fxaccounts:login 1666896949413 FirefoxAccounts DEBUG Webchannel is logging a user in. 1666896949414 FirefoxAccounts DEBUG setSignedInUser - aborting any existing flows 1666896949414 FirefoxAccounts DEBUG removing account data 1666896949414 FirefoxAccounts TRACE starting write of json user data: null 1666896949420 FirefoxAccounts TRACE finished write of json user data - took: 6 1666896949421 FirefoxAccounts TRACE storage set finished clearing account data 1666896949421 FirefoxAccounts DEBUG account data reset 1666896949421 FirefoxAccounts TRACE StorageManager finalizing 1666896949421 FirefoxAccounts TRACE StorageManager finalized 1666896949421 FirefoxAccounts TRACE initializing new storage manager 1666896949421 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified"] 1666896949421 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified"] 1666896949427 FirefoxAccounts TRACE finished write of json user data - took: 6 1666896949427 FirefoxAccounts DEBUG writing secure storage: ["keyFetchToken","unwrapBKey"] 1666896949427 FirefoxAccounts TRACE starting write of user data to the login manager 1666896949430 FirefoxAccounts TRACE finished write of user data to the login manager 1666896949430 FirefoxAccounts TRACE initializing of new storage manager done 1666896949430 FirefoxAccounts DEBUG Notifying observers of fxaccounts:onlogin 1666896949430 Sync.SyncAuthManager DEBUG observed fxaccounts:onlogin 1666896949430 Sync.SyncAuthManager INFO Sync is not configured, so ignoring the notification 1666896949431 FirefoxAccounts DEBUG FxAccountsProfileClient: Initialized 1666896949431 FirefoxAccounts TRACE FxAccountsPush registerPushEndpoint 1666896949431 FirefoxAccounts DEBUG FxAccountsProfileClient: Requested profile 1666896949431 FirefoxAccounts DEBUG getOAuthToken enter 1666896949432 FirefoxAccounts INFO fetching updated device list 1666896949436 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/devices 1666896949437 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/token 1666896949437 Services.Common.RESTRequest DEBUG POST Length: 81 1666896949632 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/devices 200 1666896949632 Hawk DEBUG (Response) /account/devices: code: 200 - Status text: OK 1666896949632 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -632 1666896949633 FirefoxAccounts INFO Got new device list: 0575fce8a83441194ff41aabf88ed6a6, 5790c02ec996fa7b79cf906cc5ab10ef, 58d283f6d65cc69940e154669fbb3987, 6722413bbae211c5b07670bec357db68, 724bf42b67ba5d3c263dc0fd7a88da7b, a0e2c55f051756b3620d9c05adebd03f, c1e2ddb5aea78520c681fd7d04a5b698, ca4fa5169bd83f6bcf2d8318979a3c60 1666896949633 FirefoxAccounts INFO updating the cache 1666896949637 FirefoxAccounts DEBUG FxAccountsPush got subscription 1666896949638 FirefoxAccounts INFO Generating and persisting encrypted sendtab keys 1666896949638 FirefoxAccounts INFO Could not find sendtab keys, generating them 1666896949640 FirefoxAccounts DEBUG _updateAccountData with items: ["device"] 1666896949640 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device"] 1666896949640 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device"] 1666896949642 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/account/scoped-key-data 1666896949642 Services.Common.RESTRequest DEBUG POST Length: 84 1666896949643 FirefoxAccounts TRACE finished write of json user data - took: 3 1666896949643 FirefoxAccounts DEBUG writing secure storage: ["keyFetchToken","unwrapBKey"] 1666896949643 FirefoxAccounts TRACE starting write of user data to the login manager 1666896949647 FirefoxAccounts TRACE finished write of user data to the login manager 1666896949723 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/token 200 1666896949723 Hawk DEBUG (Response) /oauth/token: code: 200 - Status text: OK 1666896949723 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -723 1666896949723 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"] 1666896949723 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens"] 1666896949723 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens"] 1666896949723 Services.Common.RESTRequest DEBUG GET request to https://profile.accounts.firefox.com/v1/profile 1666896949726 FirefoxAccounts TRACE finished write of json user data - took: 3 1666896949727 FirefoxAccounts DEBUG writing secure storage: ["keyFetchToken","unwrapBKey"] 1666896949727 FirefoxAccounts TRACE starting write of user data to the login manager 1666896949731 FirefoxAccounts TRACE finished write of user data to the login manager 1666896949837 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/account/scoped-key-data 200 1666896949837 Hawk DEBUG (Response) /account/scoped-key-data: code: 200 - Status text: OK 1666896949837 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -837 1666896949837 FirefoxAccounts DEBUG Fetching keys with token true from https://api.accounts.firefox.com/v1 1666896949838 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/keys 1666896950044 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/keys 200 1666896950044 Hawk DEBUG (Response) /account/keys: code: 200 - Status text: OK 1666896950044 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -1044 1666896950045 FirefoxAccounts DEBUG Keys Obtained: https://identity.mozilla.com/apps/oldsync, sync:addon_storage 1666896950045 FirefoxAccounts DEBUG _updateAccountData with items: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash","keyFetchToken","unwrapBKey"] 1666896950045 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens"] 1666896950045 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens"] 1666896950046 Sync.BulkKeyBundle INFO BulkKeyBundle being created for undefined 1666896950047 FirefoxAccounts DEBUG _updateAccountData with items: ["encryptedSendTabKeys"] 1666896950047 FirefoxAccounts INFO registering with available commands: ["https://identity.mozilla.com/cmd/open-uri"] 1666896950047 FirefoxAccounts DEBUG registering new device details 1666896950048 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/account/device 1666896950048 Services.Common.RESTRequest DEBUG POST Length: 855 1666896950048 FirefoxAccounts TRACE finished write of json user data - took: 3 1666896950048 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"] 1666896950048 FirefoxAccounts TRACE starting write of user data to the login manager 1666896950052 FirefoxAccounts TRACE finished write of user data to the login manager 1666896950052 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys"] 1666896950052 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys"] 1666896950055 FirefoxAccounts TRACE finished write of json user data - took: 3 1666896950055 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"] 1666896950055 FirefoxAccounts TRACE starting write of user data to the login manager 1666896950059 FirefoxAccounts TRACE finished write of user data to the login manager 1666896950266 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/account/device 200 1666896950266 Hawk DEBUG (Response) /account/device: code: 200 - Status text: OK 1666896950266 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -266 1666896950266 FirefoxAccounts DEBUG _updateAccountData with items: ["device"] 1666896950266 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys"] 1666896950266 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys"] 1666896950266 FirefoxAccounts DEBUG Webchannel is enabling sync 1666896950266 Sync.Service INFO Configuring sync with current FxA user 1666896950267 Sync.SyncAuthManager DEBUG observed weave:connected 1666896950267 Sync.SyncAuthManager INFO Sync has been connected to a logged in user 1666896950268 Sync.SyncAuthManager INFO The user became verified 1666896950268 Sync.Status DEBUG Status.login: error.login.reason.no_username => success.login 1666896950268 Sync.Status DEBUG Status.service: service.client_not_configured => success.status_ok 1666896950268 Sync.SyncAuthManager INFO Doing initial sync actions 1666896950268 Sync.AddonsReconciler INFO Registering as Add-on Manager listener. 1666896950268 Sync.AddonsReconciler DEBUG Adding change listener. 1666896950268 Sync.Engine.History.Tracker INFO Adding Places observer. 1666896950270 Sync.Service DEBUG User-Agent: Firefox/106.0.2 (Windows NT 10.0; Win64; x64) FxSync/1.108.0.20221025065831.desktop 1666896950270 Sync.Service INFO Starting sync at 2022-10-27 20:55:50 in browser session hNGrrLdb42UH 1666896950270 Sync.Service DEBUG In sync: should login. 1666896950270 Sync.Service INFO User logged in successfully - verifying login. 1666896950271 Sync.SyncAuthManager DEBUG unlockAndVerifyAuthState already has (or can fetch) sync keys 1666896950271 Sync.Status DEBUG Status.login: success.login => success.status_ok 1666896950271 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 1666896950271 Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok 1666896950271 Sync.SyncAuthManager INFO Getting sync key 1666896950272 Sync.SyncAuthManager INFO Getting a sync token from: https://sync.service.mydomain.de:10001/1.0/sync/1.5 1666896950272 Sync.SyncAuthManager DEBUG Getting a token using OAuth 1666896950272 FirefoxAccounts DEBUG getOAuthToken enter 1666896950286 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/token 1666896950286 Services.Common.RESTRequest DEBUG POST Length: 127 1666896950286 FirefoxAccounts TRACE finished write of json user data - took: 20 1666896950286 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"] 1666896950286 FirefoxAccounts TRACE starting write of user data to the login manager 1666896950289 FirefoxAccounts TRACE finished write of user data to the login manager 1666896950482 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/token 200 1666896950482 Hawk DEBUG (Response) /oauth/token: code: 200 - Status text: OK 1666896950482 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -482 1666896950483 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"] 1666896950483 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys"] 1666896950483 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys"] 1666896950483 Services.Common.TokenServerClient DEBUG Beginning OAuth token exchange: https://sync.service.mydomain.de:10001/1.0/sync/1.5 1666896950483 Services.Common.RESTRequest DEBUG GET request to https://sync.service.mydomain.de:10001/1.0/sync/1.5 1666896950485 FirefoxAccounts TRACE finished write of json user data - took: 2 1666896950485 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"] 1666896950485 FirefoxAccounts TRACE starting write of user data to the login manager 1666896950489 FirefoxAccounts TRACE finished write of user data to the login manager 1666896950532 Services.Common.RESTRequest DEBUG GET https://profile.accounts.firefox.com/v1/profile 200 1666896950533 FirefoxAccounts DEBUG _updateAccountData with items: ["profileCache"] 1666896950533 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys","profileCache"] 1666896950533 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys","profileCache"] 1666896950533 FirefoxAccounts DEBUG notifying profile changed for user 0c833923111145c59aa98328e6f5201a 1666896950533 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1666896950538 FirefoxAccounts TRACE finished write of json user data - took: 5 1666896950538 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"] 1666896950538 FirefoxAccounts TRACE starting write of user data to the login manager 1666896950543 FirefoxAccounts TRACE finished write of user data to the login manager 1666896951308 Services.Common.RESTRequest DEBUG GET https://sync.service.mydomain.de:10001/1.0/sync/1.5 503 1666896951308 Services.Common.TokenServerClient DEBUG Got token response: 503 1666896951308 Services.Common.TokenServerClient INFO Server-reported error: {"location":"internal","name":"","description":"Unexpected error: unable to get a node"} 1666896951309 Sync.SyncAuthManager ERROR Non-authentication error in _fetchTokenForUser: TokenServerClientServerError({"now":"2022-10-27T18:55:51.308Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Unexpected error: unable to get a node\"}]}","response_headers":{"server":"nginx","date":"Thu, 27 Oct 2022 18:55:51 GMT","content-type":"application/json","content-length":"127","connection":"keep-alive","x-weave-timestamp":"1666896950.49","strict-transport-security":"max-age=15552000; includeSubDomains; preload"},"response_status":503})(resource://services-common/tokenserverclient.js:39:36) JS Stack trace: TokenServerClientServerError@tokenserverclient.js:99:16 _processTokenResponse@tokenserverclient.js:312:19 _tokenServerExchangeRequest@tokenserverclient.js:245:19 1666896951309 Sync.Status DEBUG Status.login: success.status_ok => error.login.reason.network 1666896951309 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 1666896951309 Sync.SyncAuthManager INFO Failed to fetch the cluster URL: TokenServerClientServerError({"now":"2022-10-27T18:55:51.308Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Unexpected error: unable to get a node\"}]}","response_headers":{"server":"nginx","date":"Thu, 27 Oct 2022 18:55:51 GMT","content-type":"application/json","content-length":"127","connection":"keep-alive","x-weave-timestamp":"1666896950.49","strict-transport-security":"max-age=15552000; includeSubDomains; preload"},"response_status":503})(resource://services-common/tokenserverclient.js:39:36) JS Stack trace: TokenServerClientServerError@tokenserverclient.js:99:16 _processTokenResponse@tokenserverclient.js:312:19 _tokenServerExchangeRequest@tokenserverclient.js:245:19 1666896951309 Sync.Service DEBUG verifyLogin failed: TokenServerClientServerError({"now":"2022-10-27T18:55:51.308Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Unexpected error: unable to get a node\"}]}","response_headers":{"server":"nginx","date":"Thu, 27 Oct 2022 18:55:51 GMT","content-type":"application/json","content-length":"127","connection":"keep-alive","x-weave-timestamp":"1666896950.49","strict-transport-security":"max-age=15552000; includeSubDomains; preload"},"response_status":503})(resource://services-common/tokenserverclient.js:39:36) JS Stack trace: TokenServerClientServerError@tokenserverclient.js:99:16 _processTokenResponse@tokenserverclient.js:312:19 _tokenServerExchangeRequest@tokenserverclient.js:245:19 1666896951309 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1666896951309 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 1666896951309 Sync.ErrorHandler ERROR Sync encountered a login error 1666896951309 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1666896951310 Sync.SyncScheduler DEBUG Next sync in 3600000 ms. (why=schedule) 1666896951310 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1666896951310 Sync.Service DEBUG Exception calling WrappedLock: Error: Login failed: error.login.reason.network(resource://services-sync/service.js:1039:15) JS Stack trace: onNotify@service.js:1039:15 1666896951311 Sync.Service DEBUG Not syncing: login returned false. 1666896951311 FirefoxAccounts TRACE not checking freshness of profile as it remains recent