Closed Bug 1416788 Opened 3 years ago Closed 3 years ago

places database operations can trigger ShutdownHang crashes

Categories

(Firefox :: Sync, defect, P1)

defect

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.
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
It seems like sync or other long running optimizations could listen for xpcom shutdown notifications and abort.
See Also: → 1412351
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)
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)
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)
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%.
Depends on: 1414892, 1418443, 1417266
Flags: needinfo?(mak77)
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)
(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.
(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.
Yea, my 9 devices sounds about right.  I periodically run release/beta/nightly on desktop, laptop, and phone.
(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...)
Assignee: nobody → markh
Status: NEW → ASSIGNED
Component: Places → Sync
Priority: P3 → P1
Product: Toolkit → Firefox
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+
See Also: → 1421464
(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!
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
https://hg.mozilla.org/mozilla-central/rev/a6757a1c9800
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 59
Depends on: 1421701
Depends on: 1421703
Depends on: 1421704
You need to log in before you can comment on or make changes to this bug.