1273343 - POST failures uploading outgoing items don't log a failure reason

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

[Mark Hammond [:markh] [:mhammond]]

via TPS we are seeing logs like:

> 1463445396414	Sync.Collection	DEBUG	POST Length: 9471
> 1463445396608	Sync.Status	DEBUG	Status for engine prefs: error.engine.reason.unknown_fail
> 1463445396609	Sync.Status	DEBUG	Status.service: success.status_ok => error.sync.failed_partial
> 1463445396609	Sync.ErrorHandler	DEBUG	prefs failed: Error (resource://services-sync/resource.js:405:19) JS Stack trace: [e-mail]:98:7 < [e-mail]:398:14 < [e-mail]:439:12 < newPostQueue/[e-mail]:635:14 < [e-mail]:703:23 < [e-mail]:1506:7 < [e-mail]:1557:7 < [e-mail]:146:21 < [e-mail]:670:5 < [e-mail]:213:7 < [e-mail]:163:15 < [e-mail]:1262:7 < [e-mail]:146:21 < [e-mail]:101:16 < [e-mail]:1252:12 < sync/<@service.js:1244:14 < [e-mail]:75:16 < [e-mail]:1232:5 < [e-mail]:926:5 < [e-mail]:607:7 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:439:12 < newPostQueue/[e-mail]:635:14 < [e-mail]:703:23 < [e-mail]:1506:7 < [e-mail]:1557:7 < [e-mail]:146:21 < [e-mail]:670:5 < [e-mail]:213:7 < [e-mail]:163:15 < [e-mail]:1262:7 < [e-mail]:146:21 < [e-mail]:101:16 < [e-mail]:1252:12 < sync/<@service.js:1244:14 < [e-mail]:75:16 < [e-mail]:1232:5 < [e-mail]:926:5 < [e-mail]:607:7 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5
> 1463445396610	Sync.Engine.Passwords	DEBUG	First sync, uploading all items
> 1463445396610	Sync.Engine.Passwords	INFO	0 outgoing items pre-reconciliation
> 1463445396612	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1463445396791	Sync.Status	DEBUG	Status for engine passwords: error.engine.reason.unknown_fail
> 1463445396791	Sync.Status	DEBUG	Status.service: error.sync.failed_partial => error.sync.failed_partial
> 1463445396791	Sync.ErrorHandler	DEBUG	passwords failed: Error (resource://services-sync/resource.js:405:19) JS Stack trace: [e-mail]:98:7 < [e-mail]:398:14 < [e-mail]:425:12 < [e-mail]:1135:18 < [e-mail]:1555:7 < [e-mail]:146:21 < [e-mail]:670:5 < [e-mail]:213:7 < [e-mail]:163:15 < [e-mail]:1262:7 < [e-mail]:146:21 < [e-mail]:101:16 < [e-mail]:1252:12 < sync/<@service.js:1244:14 < [e-mail]:75:16 < [e-mail]:1232:5 < [e-mail]:926:5 < [e-mail]:607:7 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:425:12 < [e-mail]:1135:18 < [e-mail]:1555:7 < [e-mail]:146:21 < [e-mail]:670:5 < [e-mail]:213:7 < [e-mail]:163:15 < [e-mail]:1262:7 < [e-mail]:146:21 < [e-mail]:101:16 < [e-mail]:1252:12 < sync/<@service.js:1244:14 < [e-mail]:75:16 < [e-mail]:1232:5 < [e-mail]:926:5 < [e-mail]:607:7 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5 < [e-mail]:633:5

From which we can deduce that a POST failed, but can't deduce why. We need to ensure the logs capture the reasons - at least for the obvious 2 of "can't connect" and "http request failed". I'm fairly sure this isn't limited to POSTs

Comment 1

[Mark Hammond [:markh] [:mhammond]]

Attachment: Bug 1273343 - make more log noise on resource exceptions and errors.

Review commit: https://reviewboard.mozilla.org/r/74062/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/74062/

Comment 2

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8784728 [details]
Bug 1273343 - make more log noise on resource exceptions and errors.

https://reviewboard.mozilla.org/r/74062/#review71954

::: services/sync/modules/resource.js:391
(Diff revision 1)
>        return Async.waitForSyncCallback(cb);
>      } catch (ex) {
>        if (Async.isShutdownException(ex)) {
>          throw ex;
>        }
> +      this._log.warn("request to ${url} failed: ${ex}", {url: this.uri.spec, ex});

This will typically cause 2 stacks to be written twice - once here, and once at the call site - but the one written here is before it is mangled a few lines below - and this one here does include details of the network error.

Indeed, I think that mangling is the main reason we don't see a sane error already, and the stack here looks fine to me - so I'm really not sure what the code below exists for, but I'm really not up for shaving that yak currently.

Comment 3

[Thom Chiovoloni [:tcsc] (ex-moco)]

Comment on attachment 8784728 [details]
Bug 1273343 - make more log noise on resource exceptions and errors.

https://reviewboard.mozilla.org/r/74062/#review72050

Looks good to me. Eventually getting rid of the mangling might be worthwhile, but it doesn't bother me much either way.

nit: we try and have spaces inside the `{` and `}` of object literals right? r=me if I'm misremembering this or if I'm not and it's fixed.

Comment 4

[Mark Hammond [:markh] [:mhammond]]

(In reply to Thom Chiovoloni [:tcsc] from comment #3)
> nit: we try and have spaces inside the `{` and `}` of object literals right?

Given how many times I've nitted you on exactly that, that's some sweet justice for you :) Fixed! I also added "action" to the log messages.

Thanks!

Comment 5

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8784728 [details]
Bug 1273343 - make more log noise on resource exceptions and errors.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/74062/diff/1-2/

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ed6a8987ada4
make more log noise on resource exceptions and errors. r=tcsc

Comment 7

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/autoland/rev/673dcdb03f73 for https://treeherder.mozilla.org/logviewer.html#?job_id=2592265&repo=autoland

Comment 8

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8784728 [details]
Bug 1273343 - make more log noise on resource exceptions and errors.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/74062/diff/2-3/

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/717ef7ea17e8
make more log noise on resource exceptions and errors. r=tcsc

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/717ef7ea17e8