1263280 - List installed addons when writing an error log

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P3)

Description

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

Users often report Sync problems and attach error logs where a suspected culprit is an addon. It might be nice if Sync could list active addons when writing an error log to help diagnose this.

Comment 1

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

Attachment: MozReview Request: Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh

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

Comment 2

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

Comment on attachment 8746088 [details]
MozReview Request: Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh

https://reviewboard.mozilla.org/r/49251/#review46191

::: services/sync/modules/policies.js:694
(Diff revision 1)
>    },
>  
> +  _dumpAddons: function _dumpAddons() {
> +    let addonPromise = new Promise(resolve => {
> +      try {
> +        AddonManager.getAllAddons(resolve);

I think we really only care about addons of type "extension" - which you could either filter, or probably better, use getAddonsByTypes(["extension"])

We also want to skip "hidden" addons - that will skip system addons etc - so I think the filter should exclude those not active and those not hidden. The aim here is to (basically) report exactly what "about:addons" shows as active.

Thus most users should have zero listed, so maybe the heading could include the count of addons being listed, so it's clear that the heading appearing without any addons is correct (ie, making it obvious we didn't accidentally fail to list any when we should have)

::: services/sync/modules/policies.js:696
(Diff revision 1)
> +  _dumpAddons: function _dumpAddons() {
> +    let addonPromise = new Promise(resolve => {
> +      try {
> +        AddonManager.getAllAddons(resolve);
> +      } catch (e) {
> +        this._log.warn('Failed to dump addons: ${}', e)

The way the log module works makes it unnecessary to format the single arg - so this can be written as:

this._log.warn("Failed to dump addons", e);

(also note the double-quotes, which we tend to prefer, here and a few lines down - I probably failed to pick that up in other reviews!)

::: services/sync/modules/policies.js:725
(Diff revision 1)
>          Cu.reportError("Sync encountered an error - see about:sync-log for the log file.");
>        }
>      };
>      // Note we do not return the promise here - the caller doesn't need to wait
>      // for this to complete.
> +    if (this._logManager.sawError) {

this is a taste thing, but I'd prefer to avoid the duplication by always chaining off a promise - something like:

let promiseAdditional = this._logManager.sawError ? this._dumpAddons() : Promise.resolve();

promiseAdditional.then(...)

Comment 3

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

Comment on attachment 8746088 [details]
MozReview Request: Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh

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

Comment 4

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

https://reviewboard.mozilla.org/r/49251/#review46191

> I think we really only care about addons of type "extension" - which you could either filter, or probably better, use getAddonsByTypes(["extension"])
> 
> We also want to skip "hidden" addons - that will skip system addons etc - so I think the filter should exclude those not active and those not hidden. The aim here is to (basically) report exactly what "about:addons" shows as active.
> 
> Thus most users should have zero listed, so maybe the heading could include the count of addons being listed, so it's clear that the heading appearing without any addons is correct (ie, making it obvious we didn't accidentally fail to list any when we should have)

Hm, you don't think plugins could be a concern as well?

Comment 5

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

Comment on attachment 8746088 [details]
MozReview Request: Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh

https://reviewboard.mozilla.org/r/49251/#review46367

awesome, thanks!

Comment 6

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

(In reply to Thom Chiovoloni [:tcsc] from comment #4)
> Hm, you don't think plugins could be a concern as well?

Not really - I've never seen it in practice, and adds tend to handle certain content types, which would probably have trouble interacting with Sync even if it tried. We're not really trying to list potential malware or anything.

Comment 7

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/f58bd13402ee

Comment 8

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Backed out for XPCshell failure in test_errorhandler_filelog.js

Backout: https://hg.mozilla.org/integration/fx-team/rev/aea9eee926979ec130fa3a1a32bdcede88b82a35
Push with failures: https://treeherder.mozilla.org/#/jobs?repo=fx-team&revision=f58bd13402ee8c40e6f2e48bdecc28b372a9c9db
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=9088421&repo=fx-team
19:32:46     INFO -  TEST-PASS | services/sync/tests/unit/test_errorhandler_filelog.js | test_logOnSuccess_true - [test_logOnSuccess_true : 106] true == true
19:32:46     INFO -  TEST-PASS | services/sync/tests/unit/test_errorhandler_filelog.js | test_logOnSuccess_true - [test_logOnSuccess_true : 108] ".txt" == ".txt"
19:32:46     INFO -  TEST-PASS | services/sync/tests/unit/test_errorhandler_filelog.js | test_logOnSuccess_true - [test_logOnSuccess_true : 109] success-sync-1461983566456.txt - true == true
19:32:46  WARNING -  TEST-UNEXPECTED-FAIL | services/sync/tests/unit/test_errorhandler_filelog.js | test_logOnSuccess_true - [test_logOnSuccess_true : 110] false == true
19:32:46     INFO -  /builds/slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_errorhandler_filelog.js:onResetFileLog:110
19:32:46     INFO -  resource://services-common/observers.js:Observer.prototype.observe:130
19:32:46     INFO -  resource://services-common/observers.js:this.Observers.notify:89
19:32:46     INFO -  resource://services-sync/policies.js:resetFileLog/onComplete:718
19:32:46     INFO -  /builds/slave/test/build/tests/xpcshell/head.js:_do_main:209
19:32:46     INFO -  /builds/slave/test/build/tests/xpcshell/head.js:_execute_test:533
19:32:46     INFO -  -e:null:1

Comment 9

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

Ah, ****. I must have forgotten to run tests again after applying Mark's suggestions.

Regardless, this was surprisingly tricky to track down. Basically, the issue is that we don't start flushing the log file as soon as the resetLogFile function is called (since we wait for Promise.resolve().then to get around to it). 

The long and short of it is that by the time the code runs, we have created two log files, one for sync finishing, and one for the sync error. In general, I think this is what we want, but I don't think it's a good idea to change the test in this case, since it's probably worth ensuring that we don't actually write two log files in every case (or something).

Comment 10

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

Comment on attachment 8746088 [details]
MozReview Request: Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh

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

Comment 11

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

I don't quite understand this:

The failure is
> 19:32:46  WARNING -  TEST-UNEXPECTED-FAIL | services/sync/tests/unit/test_errorhandler_filelog.js | test_logOnSuccess_true - [test_logOnSuccess_true : 110] false == true

which is https://dxr.mozilla.org/mozilla-central/rev/77cead2cd20300623eea2416bc9bce4d5021df09/services/sync/tests/unit/test_errorhandler_filelog.js#110

(In reply to Thom Chiovoloni [:tcsc] from comment #9)
> Regardless, this was surprisingly tricky to track down. Basically, the issue
> is that we don't start flushing the log file as soon as the resetLogFile
> function is called (since we wait for Promise.resolve().then to get around
> to it).

Yes, but resetFileLog() sends an observer notification when complete and the test in question is waiting for that observer, so best I can tell, that test *is* waiting for the log file to be fully written - and I can't see why anything else would be running at that point.

> The long and short of it is that by the time the code runs, we have created
> two log files, one for sync finishing, and one for the sync error.

That's not what I'm expecting to happen - each sync that completes with an error should write a single error log. Each sync that completes successfully should write a single log if logOnSuccess is true, or no file otherwise. IOW, each sync should write exactly 0 or 1 logs. IOW, each sync will cause *either* "weave:service:sync:error" or "weave:service:sync:finish" notifications, but not both, so there should be exactly 1 resetFileLog call per Sync (ignoring login errors, but I don't think we are seeing them here)

Further, I'm confused by the fact an error log is being written at all in this case - the xpcshell tests run in order and none of the earlier tests create error logs - so I'm not sure how this new branch is being called by this new test at the time is fails - I'd expect test_sync_error_logOnError_true to be the first test in that file that hits your branch.

I'm probably missing something obvious...

Comment 12

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

Nice catch, turns out it was just an earlier test failing to clean up after itself, which caused the interleaved notifications. This makes more sense now.

Comment 13

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

Comment on attachment 8746088 [details]
MozReview Request: Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh

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

Comment 14

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

https://reviewboard.mozilla.org/r/49251/#review47961

Awesome, thanks!

Comment 15

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/b02b83d3af40

Comment 16

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/integration/fx-team/rev/b02b83d3af40

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b02b83d3af40