Closed
Bug 1416788
Opened 6 years ago
Closed 6 years ago
places database operations can trigger ShutdownHang crashes
Categories
(Firefox :: Sync, defect, P1)
Firefox
Sync
Tracking
()
RESOLVED
FIXED
Firefox 59
| Tracking | Status | |
|---|---|---|
| firefox59 | --- | fixed |
People
(Reporter: bkelly, Assigned: markh)
References
Details
Attachments
(1 file)
Today I experienced a shutdown hang crash: https://crash-stats.mozilla.com/report/index/3b9cbf9a-d823-4918-9d8c-75bc60171113 The stack is in the places::History code. I'm fairly sure this hang is due to trying to close firefox while sync was updating my profile. I had just launched the profile for the first time in a month or so. So it was probably trying to update a lot of data. Not sure if this belongs in places or sync component.
|
||
Comment 1•6 years ago
|
||
The work in bug 1332225 may help with Sync. Apart from general History perf improvements, I'm not sure how we should proceed here.
Priority: -- → P3
|
Reporter | |
Comment 2•6 years ago
|
||
It seems like sync or other long running optimizations could listen for xpcom shutdown notifications and abort.
|
|
Reporter | |
Comment 3•6 years ago
|
||
Kit, I just got this again today and it seems I'm running a FF58 beta with bug 1412351. What do you think? https://crash-stats.mozilla.com/report/index/189f09e8-9a05-4744-986d-dc6f20171120 Which shows the buildid is: 20171115114231 I'm fairly certain this was running sync when I shutdown.
Flags: needinfo?(kit)
|
Assignee | |
Comment 4•6 years ago
|
||
Interesting - in that most recent crash we are seeing Thread 53 in mozilla::places::History::InsertPlace(mozilla::places::VisitData&, bool). I could imagine that if we were attempting to insert many history visits we'd see this (so we should try and reproduce it locally) but it seems odd this would happen regularly (which might indicate there's some other problem causing us to sync all of history on every sync or something). Ben, would it be possible to see if about:sync-log has any recent entries and attach the most recent here? If it doesn't, please flip services.sync.log.appender.file.logOnSuccess to true, perform a sync and grab the "success" log it creates - we're particularly interested to see what the "history" engine is doing each sync.
Flags: needinfo?(bkelly)
|
|
Assignee | |
Comment 5•6 years ago
|
||
I can reproduce this hang simply by calling PlacesUtils.history.insertMany() with many visits, then shutting down the browser. The DB thread is executing https://searchfox.org/mozilla-central/rev/919dce54f43356c22d6ff6b81c07ef412b1bf933/toolkit/components/places/History.cpp#980 and as the comment there says, the intention really is to block the main thread. What makes it worse is that this happens quite early during shutdown - so when we crash, nothing has seen (say) "xpcom-shutdown" - the main thread is blocked trying to send places-shutdown. A work-around is to have Sync (or maybe insertMany itself in History.jsm) chunk up the calls to insertMany, but that seems quite terrible - maybe that History.cpp loop needs to take the hit of getting the mutex and handling shutdown itself every x iterations? That seems better than chunking at the JS layer... Mak, any thoughts? (And Ben, your logs will still be interesting because the volume of visits needed to crash is fairly high, and the fact you've this multiple times might point at a Sync issue we don't otherwise know about)
Flags: needinfo?(kit) → needinfo?(mak77)
|
|
||
Comment 6•6 years ago
|
||
How long is the shutdown crash hang timeout? (In reply to Mark Hammond [:markh] from comment #5) > A work-around is to have Sync (or maybe insertMany itself in History.jsm) > chunk up the calls to insertMany, but that seems quite terrible - maybe that > History.cpp loop needs to take the hit of getting the mutex and handling > shutdown itself every x iterations? That seems better than chunking at the > JS layer... Imo, chunking is not a so terrible solution, even on the consumer (sync) side. How many entries does currently Sync try to insert at once in the worst case? Chunking in History.cpp is also a possibility. We'll increase a bit the risk of dataloss, since after the first chunk is done, we could be deep in shutdown, and just give up on the next ones. Not that crashing is much better, and even chunking consumer side may dataloss, but at least it would be a conscious choice of the consumer. I don't have particular feeling towards one of the two solutions. > Mak, any thoughts? The work that is happening in dependencies of bug 1332225 (that I'm also adding here as dependencies) should help a lot here. Current Nightly should already be quite faster than 58 when inserting chunks of history. And there are other 2 tracked dependencies that may improve by another 50%.
|
|
Reporter | |
Comment 7•6 years ago
|
||
My about:sync-log has a couple entries. Here is the most recent: 1511206876647 Sync.Service INFO Loading Weave 1.59.0 1511206876649 Sync.Engine.Clients DEBUG Engine constructed 1511206876649 Sync.Engine.Clients DEBUG Resetting clients last sync time 1511206876651 Sync.Engine.Clients DEBUG SyncEngine initialized: clients 1511206876657 Sync.Engine.Addons DEBUG Engine constructed 1511206876657 Sync.Engine.Addons DEBUG SyncEngine initialized: addons 1511206876658 Sync.AddonsReconciler DEBUG No data seen in loaded file: addonsreconciler 1511206876664 Sync.Engine.Bookmarks DEBUG Engine constructed 1511206876665 Sync.Engine.Bookmarks DEBUG SyncEngine initialized: bookmarks 1511206876666 Sync.Engine.Forms DEBUG Engine constructed 1511206876667 Sync.Engine.Forms DEBUG SyncEngine initialized: forms 1511206876669 Sync.Engine.History DEBUG Engine constructed 1511206876670 Sync.Engine.History DEBUG SyncEngine initialized: history 1511206876671 Sync.Engine.Passwords DEBUG Engine constructed 1511206876672 Sync.Engine.Passwords DEBUG SyncEngine initialized: passwords 1511206876673 Sync.Engine.Prefs DEBUG Engine constructed 1511206876674 Sync.Engine.Prefs DEBUG SyncEngine initialized: prefs 1511206876676 Sync.Engine.Tabs DEBUG Engine constructed 1511206876676 Sync.Engine.Tabs DEBUG SyncEngine initialized: tabs 1511206876677 Sync.Engine.Tabs DEBUG Resetting tabs last sync time 1511206876678 Sync.Engine.Extension-Storage DEBUG Engine constructed 1511206876679 Sync.Engine.Extension-Storage DEBUG SyncEngine initialized: extension-storage 1511206876681 Sync.Engine.Addresses DEBUG Engine constructed 1511206876681 Sync.Engine.Addresses DEBUG SyncEngine initialized: addresses 1511206876682 Sync.Service INFO Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko/20100101 Firefox/57.0 1511206876683 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1511206876683 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1511206876683 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1511206876683 Sync.Tracker.History INFO Adding Places observer. 1511206876685 Sync.Tracker.Bookmarks DEBUG migrateOldEntries: Missing bookmarks tracker file; skipping migration 1511206876685 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1511206885030 FirefoxAccounts DEBUG FxAccountsPush loading service 1511206885030 FirefoxAccounts DEBUG FxAccountsPush initialized 1511206885139 FirefoxAccounts DEBUG FxAccountsPush got subscription 1511206885139 FirefoxAccounts DEBUG updating existing device details 1511206885141 Services.Common.RESTRequest TRACE local time, offset: 1511206885141, -1131 1511206885141 Services.Common.RESTRequest TRACE hawk auth header: Hawk id="5fb4e4064d62a4a4682e84813854fc7af0b94105fa93c9d205e488a317a70bd3", ts="1511206884", nonce="GrtgkZQGUpk=", hash="lv0Ydw//3vJVxYzNyqeiY7ieLjBC+d2t24qg04aeUSk=", mac="StHDkfj1KOYH7PbW/aVTKpeB71f1ubUAn7kP7VLllRA=" 1511206885142 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/account/device 1511206885142 Services.Common.RESTRequest TRACE HTTP Header authorization: ***** (suppressed) 1511206885142 Services.Common.RESTRequest TRACE HTTP Header content-type: application/json 1511206885142 Services.Common.RESTRequest TRACE HTTP Header accept-language: en-US, en 1511206885142 Services.Common.RESTRequest DEBUG POST Length: 432 1511206885142 Services.Common.RESTRequest TRACE POST Body: {"id":"68e24363e0822882e496ca8e423eeea3","name":"bkelly’s Firefox on valen","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABaEy_kWWWIXiYrCrNMPqZXq0O6QQJCWYl8JgRfdloTz2w_gnhR2BGXFed8WiKuHr39ZkW2gmv-g81eOqaCMzED7INdEqQAkMuW2HsrwtuGVvOinkKfy8DZRsJ0xYK30NgxbYJM","pushPublicKey":"BF3qZxmTPC0hznugEKXaPd5HOPKE3RMIslIO5vKHU8fdKTQddibMNmTy8iQgdhH4gr3gGH2z-xC2jTzNAcrW2_M","pushAuthKey":"l4LobAHyH5_1r13jXx7HPg"} 1511206885258 Services.Common.RESTRequest TRACE onStartRequest: POST https://api.accounts.firefox.com/v1/account/device 1511206885259 Services.Common.RESTRequest TRACE Channel for POST https://api.accounts.firefox.com/v1/account/device returned status code 0 1511206885259 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/account/device 200 1511206885259 Services.Common.RESTRequest TRACE POST body: {"pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABaEy_kWWWIXiYrCrNMPqZXq0O6QQJCWYl8JgRfdloTz2w_gnhR2BGXFed8WiKuHr39ZkW2gmv-g81eOqaCMzED7INdEqQAkMuW2HsrwtuGVvOinkKfy8DZRsJ0xYK30NgxbYJM","pushPublicKey":"BF3qZxmTPC0hznugEKXaPd5HOPKE3RMIslIO5vKHU8fdKTQddibMNmTy8iQgdhH4gr3gGH2z-xC2jTzNAcrW2_M","pushAuthKey":"l4LobAHyH5_1r13jXx7HPg","pushEndpointExpired":false,"id":"68e24363e0822882e496ca8e423eeea3","name":"bkelly’s Firefox on valen","type":"desktop"} 1511206885259 Hawk DEBUG (Response) /account/device: code: 200 - Status text: OK 1511206885259 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -1259 1511206885259 FirefoxAccounts DEBUG _updateAccountData with items: ["deviceId","deviceRegistrationVersion"] 1511206885260 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","deviceId","deviceRegistrationVersion","oauthTokens","profileCache"] 1511206885265 FirefoxAccounts DEBUG writing secure storage: ["kA","kB"] 1511206887686 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1511206887687 Sync.Service DEBUG User-Agent: Firefox/57.0 (Windows NT 10.0; Win64; x64) FxSync/1.59.0.20171102181127.desktop 1511206887687 Sync.Service INFO Starting sync at 2017-11-20 14:41:27 in browser session iwCdv0AJG1ly 1511206887687 Sync.Service DEBUG In sync: should login. 1511206887687 Sync.Service INFO Logging in the user. 1511206887688 Sync.BrowserIDManager INFO Waiting for user to be verified. 1511206887688 FirefoxAccounts DEBUG already verified 1511206887688 Sync.BrowserIDManager INFO Starting fetch for key bundle. 1511206887688 FirefoxAccounts DEBUG already verified 1511206887688 Sync.BrowserIDManager INFO Getting an assertion from: https://token.services.mozilla.com/1.0/sync/1.5 1511206887688 FirefoxAccounts DEBUG enter getAssertion() 1511206887689 FirefoxAccounts DEBUG getKeypairAndCertificate: already have keyPair and certificate 1511206887689 FirefoxAccounts DEBUG getAssertionFromCert 1511206887689 FirefoxAccounts DEBUG getAssertionFromCert returning signed: true 1511206887689 Sync.BrowserIDManager DEBUG Getting a token 1511206887690 Common.TokenServerClient DEBUG Beginning BID assertion exchange: https://token.services.mozilla.com/1.0/sync/1.5 1511206887690 Services.Common.RESTRequest DEBUG GET request to https://token.services.mozilla.com/1.0/sync/1.5 1511206887690 Services.Common.RESTRequest TRACE HTTP Header accept: application/json 1511206887690 Services.Common.RESTRequest TRACE HTTP Header authorization: ***** (suppressed) 1511206887690 Services.Common.RESTRequest TRACE HTTP Header x-client-state: 96097738e8e2556569995ede1204c15e 1511206888039 Services.Common.RESTRequest TRACE onStartRequest: GET https://token.services.mozilla.com/1.0/sync/1.5 1511206888040 Services.Common.RESTRequest TRACE Channel for GET https://token.services.mozilla.com/1.0/sync/1.5 returned status code 0 1511206888040 Services.Common.RESTRequest DEBUG GET https://token.services.mozilla.com/1.0/sync/1.5 200 1511206888040 Services.Common.RESTRequest TRACE GET body: {"uid": 65320086, "hashalg": "sha256", "api_endpoint": "https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086", "duration": 3600, "key": "mFYGRW3suwcs9Hi2rk1u-EL3oOcoalFKiWSr4ZbtRAI=", "hashed_fxa_uid": "15be93d80dce74acd19c644e357e9d78", "id": "eyJub2RlIjogImh0dHBzOi8vc3luYy00NTktdXMtd2VzdC0yLnN5bmMuc2VydmljZXMubW96aWxsYS5jb20iLCAidWlkIjogNjUzMjAwODYsICJleHBpcmVzIjogMTUxMTIxMDQ4NywgImZ4YV91aWQiOiAiMTViZTkzZDgwZGNlNzRhY2QxOWM2NDRlMzU3ZTlkNzgiLCAic2FsdCI6ICJhODZhZjUiLCAiZGV2aWNlX2lkIjogIjk2OTAwOWZmMjM1MmU4N2IwODM4ODJmMmI3Mzk1N2UyIn0dOO31OkSeMiaoj2msl9mK-Qb48XeoXUWTDKig1ooaeA=="} 1511206888040 Common.TokenServerClient DEBUG Got token response: 200 1511206888040 Common.TokenServerClient DEBUG Successful token response 1511206888040 Sync.BrowserIDManager DEBUG Successfully got a sync token 1511206888041 Sync.BulkKeyBundle INFO BulkKeyBundle being created for undefined 1511206888041 Sync.BrowserIDManager INFO Background fetch for key bundle done 1511206888041 Sync.Status DEBUG Status.login: success.login => success.login 1511206888041 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1511206888041 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1511206888041 Sync.Service INFO User logged in successfully - verifying login. 1511206888041 Sync.BrowserIDManager DEBUG unlockAndVerifyAuthState already has (or can fetch) sync keys 1511206888041 Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok 1511206888041 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206888041 Sync.BrowserIDManager DEBUG _findCluster returning https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/ 1511206888041 Sync.BrowserIDManager DEBUG Cluster value = https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/ 1511206888041 Sync.BrowserIDManager DEBUG Setting cluster to https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/ 1511206888041 Sync.Service DEBUG Caching URLs under storage user base: https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/ 1511206888042 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206888390 Sync.AsyncResource DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/collections 1511206888390 Sync.AsyncResource DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/collections 1511206888391 Sync.Service DEBUG Fetching server configuration: https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/configuration 1511206888391 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206888487 Sync.AsyncResource DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/configuration 1511206888487 Sync.AsyncResource DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/configuration 1511206888487 Sync.Service DEBUG Fetching global metadata record 1511206888488 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206888585 Sync.AsyncResource DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/meta/global 1511206888585 Sync.AsyncResource DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/meta/global 1511206888585 Sync.Service DEBUG Clearing cached meta record. metaModified is undefined, setting to 1510944492.64 1511206888586 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206888681 Sync.AsyncResource DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/meta/global 1511206888681 Sync.AsyncResource DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/meta/global 1511206888682 Sync.Service DEBUG Weave Version: 1.59.0 Local Storage: 5 Remote Storage: 5 1511206888682 Sync.Service DEBUG Fetching and verifying -- or generating -- symmetric keys. 1511206888682 Sync.Service INFO Testing info/collections: {"tabs":1511206653.39,"clients":1511199186.43,"crypto":1489524125.7,"forms":1511206653.5,"meta":1510944492.64,"bookmarks":1511199487.23,"prefs":1510860640.29,"history":1511206653.78} 1511206888682 Sync.CollectionKeyManager INFO Testing for updateNeeded. Last modified: 0 1511206888682 Sync.Service INFO collection keys reports that a key update is needed. 1511206888682 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206888869 Sync.AsyncResource DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/crypto/keys 1511206888869 Sync.AsyncResource DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/crypto/keys 1511206888869 Sync.CollectionKeyManager INFO Updating collection keys... 1511206888870 Sync.CollectionKeyManager INFO Setting collection keys contents. Our last modified: 0, input modified: 1489524125.7. 1511206888870 Sync.BulkKeyBundle INFO BulkKeyBundle being created for [default] 1511206888870 Sync.CollectionKeyManager INFO Processing downloaded per-collection keys. 1511206888870 Sync.CollectionKeyManager INFO Clearing collection keys... 1511206888870 Sync.CollectionKeyManager INFO Saving downloaded keys. 1511206888870 Sync.CollectionKeyManager INFO Bumping last modified to 1489524125.7 1511206888870 Sync.CollectionKeyManager INFO Collection keys updated. 1511206888870 Sync.Status DEBUG Status.login: success.login => success.login 1511206888870 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1511206888870 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1511206888870 Sync.Telemetry TRACE observed weave:service:sync:start 1511206888871 Sync.Status INFO Resetting Status. 1511206888871 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1511206888872 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206888970 Sync.AsyncResource DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/collections?v=1.59.0 1511206888970 Sync.AsyncResource DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/collections?v=1.59.0 1511206888971 Sync.Service DEBUG Fetching server configuration: https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/configuration 1511206888972 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206889076 Sync.AsyncResource DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/configuration 1511206889076 Sync.AsyncResource DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/info/configuration 1511206889077 Sync.Service DEBUG Fetching global metadata record 1511206889077 Sync.Service DEBUG Weave Version: 1.59.0 Local Storage: 5 Remote Storage: 5 1511206889077 Sync.Service DEBUG Fetching and verifying -- or generating -- symmetric keys. 1511206889077 Sync.Service INFO Testing info/collections: {"tabs":1511206653.39,"clients":1511199186.43,"crypto":1489524125.7,"forms":1511206653.5,"meta":1510944492.64,"bookmarks":1511199487.23,"prefs":1510860640.29,"history":1511206653.78} 1511206889077 Sync.CollectionKeyManager INFO Testing for updateNeeded. Last modified: 1489524125.7 1511206889077 Sync.Synchronizer DEBUG Refreshing client list. 1511206889077 Sync.Telemetry TRACE observed weave:engine:sync:start clients 1511206889078 Sync.Engine.Clients DEBUG First sync, uploading all items 1511206889079 Sync.Engine.Clients INFO 1 outgoing items pre-reconciliation 1511206889080 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206889182 Sync.Collection DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/clients?full=1&limit=1000 1511206889182 Sync.Collection DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/clients?full=1&limit=1000 1511206889189 Sync.Engine.Clients INFO Records: 8 applied, 8 successfully, 0 failed to apply, 0 newly failed to apply, 1 reconciled. 1511206889190 Sync.Telemetry TRACE observed weave:engine:sync:applied clients 1511206889190 Sync.Engine.Clients DEBUG Refreshing the known stale clients list 1511206889190 Services.Common.RESTRequest TRACE local time, offset: 1511206889190, -1259 1511206889190 Services.Common.RESTRequest TRACE hawk auth header: Hawk id="5fb4e4064d62a4a4682e84813854fc7af0b94105fa93c9d205e488a317a70bd3", ts="1511206887", nonce="vTdU/4Ij8MA=", mac="ofuH5tXCepTCyzl9WnHhZh5c55kB+9aNkzVOVii6EFU=" 1511206889191 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/devices 1511206889191 Services.Common.RESTRequest TRACE HTTP Header authorization: ***** (suppressed) 1511206889191 Services.Common.RESTRequest TRACE HTTP Header content-type: text/plain 1511206889191 Services.Common.RESTRequest TRACE HTTP Header accept-language: en-US, en 1511206889315 Services.Common.RESTRequest TRACE onStartRequest: GET https://api.accounts.firefox.com/v1/account/devices 1511206889316 Services.Common.RESTRequest TRACE Channel for GET https://api.accounts.firefox.com/v1/account/devices returned status code 0 1511206889316 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/devices 200 1511206889316 Services.Common.RESTRequest TRACE GET body: [{"id":"038cf73d802394ae58231f0651e78f69","isCurrentDevice":false,"location":{"city":"Pittsford","country":"United States","state":"New York","stateCode":"NY"},"name":"bkelly’s Firefox on xykon","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZve4-Y3uwsqVRdyTK70DR_FfzFD2Z2mGMby4fCLn_sZC85xhidntZ2YLLgOFcnFcaYZ9FpmLXPfHr-kZGRc1v3zozP5OJ8-j55TI211cHCfI9DwMSYsK4DqPfw0EMxlln3DHr","pushPublicKey":"BPAmT-0rifsnV9YlBcZJ9Bd0YeFbEFYkKDhY2aQt5iWVKLYk22P44Wsbqunav2a_wO3s0izXfbhzv25mf9vXFKo","pushAuthKey":"6tZ1ek_-kifpjIkPPZpzag","pushEndpointExpired":false,"lastAccessTime":1510969759139,"lastAccessTimeFormatted":"3 days ago"},{"id":"2425a60e238ce93187a049943a19bfbf","isCurrentDevice":false,"location":{},"name":"bkelly's Firefox on kosh","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1470419546545,"lastAccessTimeFormatted":"a year ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"29607d886959a551797814c14c9b698b","isCurrentDevice":false,"location":{"city":"Pittsford","country":"United States","state":"New York","stateCode":"NY"},"name":"bkelly’s Nightly on Intel Mac OS X 10.12","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABaCL4jaJhNmlfgCG7q4EfJSFOBlWgYEYNRVoDLg9s8DiC9Zjhfk3YQ5iOLFdG98g2fUlzAYoKAgdJhNWNBUcUbCqqry2mooriLf8HsR43Y0CA-gYT_AxsOrIjPob07rDNN5hWi","pushPublicKey":"BLSCxWAYtTousERrhdJDuBDpa1LC2PLoZb7pV2Uvis4sWgWKJCWhq6h7R0jgFtjoPpMpInIpe_G0vINlGNcd7YI","pushAuthKey":"b3bU2nYlSBA7mXbQD7NjvA","pushEndpointExpired":false,"lastAccessTime":1511140206700,"lastAccessTimeFormatted":"19 hours ago"},{"id":"3eac1885bf192c155a458e5f447b832f","isCurrentDevice":false,"location":{"city":"Pittsford","country":"United States","state":"New York","stateCode":"NY"},"name":"bkelly’s Firefox Developer Edition on valen","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZSUfT4foQURpEytymHZTmtT2mefB38gYy2od8BGIjESqUDJpt5l8gclGg88CHsX6PA9AJ2WF2hPwU5nQBRaf9za5fL5_GDa1PtmLJYtnE1_iq3eM6xAIFCZ8kL4cx277ibkoZ","pushPublicKey":"BEri6lCbUkPrRQgyC5XM3fue2tYNJYuMjHED7Y4aZY3o1pjiDCUlqpTT2ex1ZJXO-5ySArR3Fspk2WGtez-QTF4","pushAuthKey":"oo9WG72Li3-Y0ABh4sSSXQ","pushEndpointExpired":false,"lastAccessTime":1511199184663,"lastAccessTimeFormatted":"2 hours ago"},{"id":"56c3e83d1c0e22afcf5d601382716985","isCurrentDevice":false,"location":{},"name":"bkelly's Firefox on vir","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1492647170687,"lastAccessTimeFormatted":"7 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"5e0cfe0267c706df183e3c205639011f","isCurrentDevice":false,"location":{"country":"United States","state":"New York"},"name":"Beta on Nexus 5X","type":"mobile","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZ5gAnS5fuiijKXXB0gPbmySid7ZJAZGBoIowOdYi6khZanJiOTFqnmCFbBEDIj560E1szyClF-_vNjgG495jnpbIcuKFKeJFtyFx3Ssz7OeCECes6GcjCDGaOR-73yTXW4SJr","pushPublicKey":"BKDJOvWNiRyX7nRjylMFf_C7iQ3L0OMNGMZGnVEnJmxImQwfXf2gIPXwMCHknSZsoGR4WuiaXhdT7EHI-I4dQEo","pushAuthKey":"xcJvK4H6LSeskTCuSvHCmQ","pushEndpointExpired":false,"lastAccessTime":1509555813851,"lastAccessTimeFormatted":"19 days ago"},{"id":"68e24363e0822882e496ca8e423eeea3","isCurrentDevice":true,"location":{"city":"Pittsford","country":"United States","state":"New York","stateCode":"NY"},"name":"bkelly’s Firefox on valen","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABaEy_kWWWIXiYrCrNMPqZXq0O6QQJCWYl8JgRfdloTz2w_gnhR2BGXFed8WiKuHr39ZkW2gmv-g81eOqaCMzED7INdEqQAkMuW2HsrwtuGVvOinkKfy8DZRsJ0xYK30NgxbYJM","pushPublicKey":"BF3qZxmTPC0hznugEKXaPd5HOPKE3RMIslIO5vKHU8fdKTQddibMNmTy8iQgdhH4gr3gGH2z-xC2jTzNAcrW2_M","pushAuthKey":"l4LobAHyH5_1r13jXx7HPg","pushEndpointExpired":false,"lastAccessTime":1511206867753,"lastAccessTimeFormatted":"a few seconds ago"},{"id":"72bc88052d75c561510922abea469cce","isCurrentDevice":false,"location":{"city":"Pittsford","country":"United States","state":"New York","stateCode":"NY"},"name":"bkelly’s Firefox on valen","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZGdqJZPuJov1ucer-ZNMfukFIirtI3tNiV9XJv_wxvLM1XeBUMO700eNSX9l80rN8Wo_8KT_A9RF0UJtwM8kqBjHJKDgN0SyK1YLr35tqQ8Vob4fEmX9XA9_cyXy_RRIiYx13","pushPublicKey":"BFWhVyH-rw_1PNs0cgx-7sZQ228goFWVRkVOUy6ScRQd26K5Z5NChludJcCV1IHljMK0FwfbrRFajO5UGYh_O00","pushAuthKey":"i2U6VC33lkHgrm5eFnZJzA","pushEndpointExpired":false,"lastAccessTime":1510936140382,"lastAccessTimeFormatted":"3 days ago"},{"id":"8c6ec0b3c810535250cbd1cd8e7eef1f","isCurrentDevice":false,"location":{},"name":"Nightly on Nexus 5X","type":"mobile","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABYI7uSdoObCO-WScBSux9nfl-CtlstjdvIZOj5C3UFOW2uHA4K7DBiwE3mkYtR9XKJslbgGKxWnqPPUCPo1rg5JVBhNSIPSr2gkvdZ_mOV3YiXAeY0ZtKy1hbMKgQt2AK8bmPy","pushPublicKey":"BJCOcb_hBSjyUCJRaceWN0iB3A29w2kge436r9oKinA62IcsRzdZa0MnFBwagD3r6nbqOSFsKpnXcnikNinmwfQ","pushAuthKey":"4hrqnkARiKzeZQiPlc8cVA","pushEndpointExpired":false,"lastAccessTime":1482224422655,"lastAccessTimeFormatted":"a year ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"8d4347c3c4263f39c1e5e6f278d18b7e","isCurrentDevice":false,"location":{"city":"Pittsford","country":"United States","state":"New York","stateCode":"NY"},"name":"bkelly’s Nightly on DESKTOP-RF4RN8N","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZ55hBqq6IVjhtjJV2x_7L-EbneoTIuyewSriPWTZ_Uc3q1KXN0XMS8_UaG3_glWD12IBrPXBeScJoLD7W-7LZvphpHS5H2_BisxCAL3C8Eidzp7GEOVykBWem-PWHPOaaKbg7","pushPublicKey":"BPxVNGjN2FQ3XKVU-mWmR8AV06QFTPWleWx1VvGn2TUH2H5zBuEAbyl3diLZVROJohnWEttnf9TvwwvPcCLVW4k","pushAuthKey":"CoMVGJkhH_uIwzuGFw6s_w","pushEndpointExpired":false,"lastAccessTime":1511193380000,"lastAccessTimeFormatted":"4 hours ago"},{"id":"955a38059a02870e9e3596403b92ae81","isCurrentDevice":false,"location":{},"name":"bkelly’s Firefox on vir","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZgMTBuOTxZ0F3DrkU2Km0CXmVXaKPsm5AB-HH8tYB-1zuhY1tJqX8cDlaEm_aS9uXLxBHK4SEeG4YLE2FQ0jTKmR-7RNjy8YqVrqD9MgFHcdrNaAs-1Db_4qVgo_a8nQcKc7A","pushPublicKey":"BBI0rfPXiJz5hvub2ZzjRboZAQdYp4glXtdct8OmWQGJfAbdeLYOOdGt9Vfr4wMHi3cbRr71iq-62FiNvpIUOtE","pushAuthKey":"7indSny0N_mJp0COnCQr7w","pushEndpointExpired":true,"lastAccessTime":1501611199818,"lastAccessTimeFormatted":"4 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"989f87a0acf7b92126e43585170ac70a","isCurrentDevice":false,"location":{"city":"Pittsford","country":"United States","state":"New York","stateCode":"NY"},"name":"Nightly on moto x4","type":"mobile","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZ-f1OVknKiI7H8KPk0G-qQejBWKpjvmXeIG1JX6H221IOEBzp8xA_eLnWsTn5MV7-GGt9tvfXoZ465UsvyefgfiBWFZ_v8M6zG9PNES0Z93yprzTm1ecpniKEj0uEOscVNfWi","pushPublicKey":"BAevcl6oiP9kayIK4_vSnKmlCrb5HvD2CsbdZPGR9GKfaphPXq61nrM5xWHSxouZ11nBKhOMkrJKtt7Ux4W_pUQ","pushAuthKey":"EgRadb4pJZwFAdlBl6o9Gg","pushEndpointExpired":false,"lastAccessTime":1511200988337,"lastAccessTimeFormatted":"2 hours ago"},{"id":"98c2d1879a6dd18ffa551b890f1461a9","isCurrentDevice":false,"location":{},"name":"Beta on Nexus 5X","type":"mobile","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1489119242859,"lastAccessTimeFormatted":"8 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"9d00179e47444bf5d51ce40255d94853","isCurrentDevice":false,"location":{},"name":"bkelly's Nightly on kosh","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1488999894513,"lastAccessTimeFormatted":"8 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"a77893574a71378b7b50584ac10fe6ef","isCurrentDevice":false,"location":{},"name":"bkelly's Nightly on vir","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1470714529350,"lastAccessTimeFormatted":"a year ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"a99eb199b036aa4bf11194911279f7a8","isCurrentDevice":false,"location":{},"name":"bkelly's Nightly on kosh","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1457619684538,"lastAccessTimeFormatted":"2 years ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"ac80c1cae8751a5679d2cbaefc20c854","isCurrentDevice":false,"location":{},"name":"bkelly's Firefox on kosh","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1488897942664,"lastAccessTimeFormatted":"8 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"bbb79aa6af78e074ea64af58d1f91989","isCurrentDevice":false,"location":{},"name":"Firefox Mobile 43, Firefox OS","type":"mobile","pushCallback":null,"pushPublicKey":null,"pushAuthKey":null,"pushEndpointExpired":false,"lastAccessTime":1492783818608,"lastAccessTimeFormatted":"7 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"c78e180bce5c04e3b3e6725ed4e702c7","isCurrentDevice":false,"location":{},"name":"bkelly’s Firefox Developer Edition on vir-2","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1486216476525,"lastAccessTimeFormatted":"10 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"cbeb493dac790f7003940d6b37a2d6d0","isCurrentDevice":false,"location":{},"name":"bkelly's Nightly on vir","type":"desktop","pushCallback":null,"pushPublicKey":null,"pushAuthKey":null,"pushEndpointExpired":false,"lastAccessTime":1453951106227,"lastAccessTimeFormatted":"2 years ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"cc3ff04a1443a09d84207943fdf08704","isCurrentDevice":false,"location":{},"name":"Firefox 41.0.2, Android","type":"tablet","pushCallback":null,"pushPublicKey":null,"pushAuthKey":null,"pushEndpointExpired":false,"lastAccessTime":1492631174973,"lastAccessTimeFormatted":"7 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"cdf567ebfa88fdbc335305153e85605e","isCurrentDevice":false,"location":{},"name":"bkelly's Firefox Developer Edition on kosh","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1489524124275,"lastAccessTimeFormatted":"8 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"cfcc7b945d0b038f74e5929fe1f3a6ad","isCurrentDevice":false,"location":{},"name":"bkelly's Firefox on kosh","type":"desktop","pushCallback":"","pushPublicKey":"","pushAuthKey":"","pushEndpointExpired":false,"lastAccessTime":1489426077519,"lastAccessTimeFormatted":"8 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"dff229d7a674d40b669541f5b2507294","isCurrentDevice":false,"location":{},"name":"Aurora on Nexus 5X","type":"mobile","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABY8MEVhqCdetJ9jNI1SUeYc3J_PqAqn2zN1Ph9svYw5HeR9ujQc49fDbZDjsOqWIPyv_9ALBfsG_lPdaJDl7b5vwkspOCaYd5otqNsF5Aon0xWbAmVxtV1NAV_FMQi8DQ5g2Jt","pushPublicKey":"BBLtLgDtPI6Y-q-xwietHE1PDOAifxtREEVF_zwgaT5R2-uAC95W2cxMoTTTuJWW6f3XwjPvpP_z2a59ySKYM7Y","pushAuthKey":"Wu-qOnt-ghlsN-DwS4l1aw","pushEndpointExpired":false,"lastAccessTime":1488978924973,"lastAccessTimeFormatted":"8 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"e6c013b195e026345532a5f3e12b5732","isCurrentDevice":false,"location":{},"name":"Firefox on Nexus 5X","type":"mobile","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABY976bx7vd-fgVYrQDwHDGHDmUWkqBDGmLBSHTrW75EW2DhU66sFG5YFp8Bgl-N3W_tHVOm4MZUq9aBDTkeoY6G-FUM91o748pTiNc579Y6Qp9MlyuAzJIMmPKsHBQWLj_IZ0S","pushPublicKey":"BFbp8i1QN9eEgDH_EpHKLvqXGqj_z4CxDWVgZR4g8dFTQYI7a_qE4F2HIzTBSfTwzujeY_cKK69pb_Mkwqydb0g","pushAuthKey":"CiG2Ie_X4cChUKpEXy9I7A","pushEndpointExpired":false,"lastAccessTime":1492621966076,"lastAccessTimeFormatted":"7 months ago","approximateLastAccessTime":1507081020000,"approximateLastAccessTimeFormatted":"2 months ago"},{"id":"f523d93135706ba273334095750633e3","isCurrentDevice":false,"location":{"city":"Pittsford","country":"United States","state":"New York","stateCode":"NY"},"name":"bkelly’s Nightly on vir","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZ5Vi6iiN625s6r0hJrk44IE9DR1sxZt2WcJgYYUzj27zSZwz6YwK407noGjetsXDg_HHX43vSNyTSv_rdoxw-yh7frL6CHOWgc43l_G97R3hPrLJEfqGLWPlYmxsmf6XhWE-v","pushPublicKey":"BPG2SnYWV3AhZ9ASYoOCWZdnxbWC54T3UFut_czLjzOUgHjDXu8t981GE7Ii4Gy8pfQQ8F62K8cfPYoBLMG-PvE","pushAuthKey":"rqJfODvY_dmULT1Yi5-8Vg","pushEndpointExpired":false,"lastAccessTime":1510461551807,"lastAccessTimeFormatted":"9 days ago"},{"id":"fa079631e5b896c87bc38809a70d094a","isCurrentDevice":false,"location":{"country":"United States","state":"New York"},"name":"Nightly on Nexus 5X","type":"mobile","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABZ7z3ZZTqR7dXu20_0jpwglrKMKRnSc08xwKh2pS4HS9Yi_pD-owcqVu5hOHfUQPcfr-pIirOiuSaLGw4VA7C9jPF-OSXgH0lLMqodTN2eH1dNiISpLl37CU5vnNlAzK_3naRZ","pushPublicKey":"BFPamlGRemELfwnpqBRyMVeOEhbPykib-O-9VhE0FX2MUdW-ctu534hyl6q30UtOkQRUc4l5EJLHARCwCpwayZw","pushAuthKey":"fxXCa8qKpN2XWFeaTmzpRQ","pushEndpointExpired":false,"lastAccessTime":1509552372725,"lastAccessTimeFormatted":"19 days ago"}] 1511206889316 Hawk DEBUG (Response) /account/devices: code: 200 - Status text: OK 1511206889316 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -1316 1511206889321 Sync.Engine.Clients INFO Posting 1 records of 529 bytes with batch=true 1511206889322 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206889322 Sync.Collection DEBUG POST Length: 529 1511206889500 Sync.Collection DEBUG mesg: POST success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/clients?batch=true&commit=true 1511206889500 Sync.Collection DEBUG POST success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/clients?batch=true&commit=true 1511206889502 Sync.Telemetry TRACE observed weave:engine:sync:uploaded clients 1511206889502 Sync.SyncScheduler DEBUG Client count: 0 -> 9 1511206889503 Sync.Telemetry TRACE observed weave:engine:sync:finish clients 1511206889503 Sync.Synchronizer INFO Updating enabled engines: 9 clients. 1511206889504 Sync.Synchronizer INFO Syncing all enabled engines. 1511206889504 Sync.Telemetry TRACE observed weave:engine:sync:start prefs 1511206889504 Sync.Engine.Prefs INFO 0 outgoing items pre-reconciliation 1511206889505 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206889632 Sync.Collection DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/prefs?newer=1507921444.89&full=1&limit=1000 1511206889632 Sync.Collection DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/prefs?newer=1507921444.89&full=1&limit=1000 1511206889639 Sync.Engine.Prefs INFO Records: 1 applied, 1 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled. 1511206889639 Sync.Telemetry TRACE observed weave:engine:sync:applied prefs 1511206889640 Sync.Telemetry TRACE observed weave:engine:sync:finish prefs 1511206889640 Sync.Telemetry TRACE observed weave:engine:sync:start tabs 1511206889640 Sync.Engine.Tabs DEBUG Engine syncIDs: _Lg4cOgoyKBs,iB-m0HeICvBP 1511206889640 Sync.Engine.Tabs DEBUG Resetting tabs last sync time 1511206889641 Sync.Engine.Tabs DEBUG First sync, uploading all items 1511206889641 Sync.Engine.Tabs INFO 1 outgoing items pre-reconciliation 1511206889642 Sync.BrowserIDManager DEBUG _ensureValidToken already has one 1511206889845 Sync.Collection DEBUG mesg: GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/tabs?full=1&limit=1000 1511206889845 Sync.Collection DEBUG GET success 200 https://sync-459-us-west-2.sync.services.mozilla.com/1.5/65320086/storage/tabs?full=1&limit=1000 1511206889851 Sync.Status DEBUG Status for engine tabs: error.engine.reason.unknown_fail 1511206889851 Sync.Status DEBUG Status.service: success.status_ok => error.sync.failed_partial 1511206889851 Sync.ErrorHandler DEBUG tabs was interrupted due to the application shutting down 1511206889851 Sync.Telemetry TRACE observed weave:engine:sync:error tabs 1511206889851 Sync.Synchronizer INFO tabs was interrupted by shutdown; no other engines will sync 1511206889851 Sync.Synchronizer INFO Aborting sync for failure in tabs 1511206889852 Sync.Doctor INFO Skipping check of prefs - disabled via preferences 1511206889852 Sync.Doctor INFO Skipping validation: no engines qualify 1511206889856 Sync.Doctor INFO bookmarks reparier did not advance. 1511206889856 Sync.Synchronizer INFO Sync completed at 2017-11-20 14:41:29 after 0.98 secs. 1511206889856 Sync.Declined DEBUG Handling remote declined: ["passwords","addons"] 1511206889856 Sync.Declined DEBUG Handling local declined: ["addons","passwords"] 1511206889857 Sync.Declined DEBUG Declined changed? false 1511206889857 Sync.Service INFO No change to declined engines. Not reuploading meta/global. 1511206889859 Sync.SyncScheduler DEBUG Next sync in 90000 ms. 1511206889859 Sync.ErrorHandler ERROR Some engines did not sync correctly. 1511206889859 Sync.Status DEBUG Status.sync: success.sync => error.sync.prolonged_failure 1511206889859 Sync.Status DEBUG Status.service: error.sync.failed_partial => error.sync.failed 1511206889859 Sync.Telemetry TRACE observed weave:service:sync:finish 1511206889862 Sync.ErrorHandler DEBUG Addons installed: 1 1511206889862 Sync.ErrorHandler DEBUG - Multi-Account Containers, version 4.0.3, id @testpilot-containers
Flags: needinfo?(bkelly)
|
|
Reporter | |
Comment 8•6 years ago
|
||
(In reply to Mark Hammond [:markh] from comment #5) > (And Ben, your logs will still be interesting because the volume of visits > needed to crash is fairly high, and the fact you've this multiple times > might point at a Sync issue we don't otherwise know about) Well, this is my beta profile and I haven't run beta in a month or so. So sync probably had a lot of stuff to pull in. I only launched beta here to trigger an update to FF58. That's why I shutdown fairly quickly as well.
|
|
Assignee | |
Comment 9•6 years ago
|
||
(In reply to Ben Kelly [:bkelly] from comment #8) > Well, this is my beta profile and I haven't run beta in a month or so. So > sync probably had a lot of stuff to pull in. I only launched beta here to > trigger an update to FF58. That's why I shutdown fairly quickly as well. Thanks Ben. Sadly that log above is a shutdown which happened before we got to the history engine, but given what you wrote above, and given the log seems to show you have 9 active devices attached to the account, I think it's reasonable to assume that you simply had collected alot of history and there's no need to assume Sync is doing more work than it needs. I'll get a simple patch up to avoid the shutdown crash ASAP.
|
|
Reporter | |
Comment 10•6 years ago
|
||
Yea, my 9 devices sounds about right. I periodically run release/beta/nightly on desktop, laptop, and phone.
| Comment hidden (mozreview-request) |
| Comment hidden (mozreview-request) |
| Comment hidden (mozreview-request) |
|
|
Assignee | |
Comment 14•6 years ago
|
||
(sorry for the mozreview spam - I was trying to setup a pre-push eslint git hook and hoping it would abort some of those pushes. I've now discovered bug 1386351 which says they don't currently work. Oh well...)
|
||
Updated•6 years ago
|
Assignee: nobody → markh
Status: NEW → ASSIGNED
Component: Places → Sync
Priority: P3 → P1
Product: Toolkit → Firefox
|
|
||
Comment 15•6 years ago
|
||
| mozreview-review | ||
Comment on attachment 8931216 [details] Bug 1416788 - limit number of visits we pass to PlacesUtils.history.insertMany to prevent shutdown hangs. https://reviewboard.mozilla.org/r/202320/#review207950 Thanks! ::: npm-shrinkwrap.json:1439 (Diff revision 3) > "sprintf-js": { > "version": "1.0.3", > "resolved": "https://registry.npmjs.org/sprintf-js/-/sprintf-js-1.0.3.tgz", > "integrity": "sha1-BOaSb2YolTVPPdAVIDYzuFcpfiw=" > }, > + "string_decoder": { Looks like these changes don't belong in this patch. I've noticed `./mach eslint` updates my `npm-shrinkwrap.json` when I run it locally, too... ::: services/sync/modules/engines/history.js:102 (Diff revision 3) > __proto__: Store.prototype, > > __asyncHistory: null, > + > + // We try and only update this many visits at one time. > + INSERT_BATCH_SIZE: 500, Let's call this something like `MAX_VISITS_PER_INSERT`, to make it clear this chunks visits, not history records. ::: services/sync/modules/engines/history.js:239 (Diff revision 3) > + // we do not split a single record into multiple records, because at some > + // time in the future, we intend to ensure these records are ordered by > + // lastModified, and advance the engine's timestamp as we process them, > + // meaning we can resume exactly where we left off next sync - although > + // currently that's not done, so we will retry the entire batch next sync > + // if interrupted. I was going to ask if it's worth fast-forwarding the last modified date above, but you beat me to it. :-) Let's land your patch as is, and get a follow-up bug on file for this. ::: services/sync/modules/engines/history.js:253 (Diff revision 3) > + do { > + let record = records.shift(); > + toAdd.push(record); > + count += record.visits.length; > + } while (records.length && > + count + records[0].visits.length <= this.INSERT_BATCH_SIZE); It took a few reads for me to wrap my head around this. To make sure I understand: we keep taking records from `records` and adding them to `toAdd` until the number of visits reaches the maximum (or exceeds, if one record has more visits). It might be clearer to rewrite this without mutating `records`, but, if that would be more confusing, this is fine.
Attachment #8931216 -
Flags: review?(kit) → review+
|
|
Assignee | |
Comment 16•6 years ago
|
||
(In reply to Kit Cambridge (he/him) [:kitcambridge] from comment #15) > Looks like these changes don't belong in this patch. I've noticed `./mach > eslint` updates my `npm-shrinkwrap.json` when I run it locally, too... Oops - thanks! > Let's call this something like `MAX_VISITS_PER_INSERT`, to make it clear > this chunks visits, not history records. done. > ::: services/sync/modules/engines/history.js:239 > (Diff revision 3) > > + // we do not split a single record into multiple records, because at some > > + // time in the future, we intend to ensure these records are ordered by > > + // lastModified, and advance the engine's timestamp as we process them, > > + // meaning we can resume exactly where we left off next sync - although > > + // currently that's not done, so we will retry the entire batch next sync > > + // if interrupted. > > I was going to ask if it's worth fast-forwarding the last modified date > above, but you beat me to it. :-) Let's land your patch as is, and get a > follow-up bug on file for this. Bug 1421464 > It took a few reads for me to wrap my head around this. To make sure I > understand: we keep taking records from `records` and adding them to `toAdd` > until the number of visits reaches the maximum (or exceeds, if one record > has more visits). Yep - I added a few more comments to try and make it clearer what is going on. > It might be clearer to rewrite this without mutating `records`, but, if that > would be more confusing, this is fine. Yeah, mutating records is a bit of a smell and it wasn't painful to not do that, so I changed the patch to just track what index we are at. Thanks!
| Comment hidden (mozreview-request) |
|
||
Comment 18•6 years ago
|
||
Pushed by mhammond@skippinet.com.au: https://hg.mozilla.org/integration/autoland/rev/a6757a1c9800 limit number of visits we pass to PlacesUtils.history.insertMany to prevent shutdown hangs. r=kitcambridge
|
||
Comment 19•6 years ago
|
||
| bugherder | ||
https://hg.mozilla.org/mozilla-central/rev/a6757a1c9800
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox59:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 59
You need to log in
before you can comment on or make changes to this bug.
Description
•