List installed addons when writing an error log

RESOLVED FIXED in Firefox 49

Status

()

Firefox
Sync
P3
normal
RESOLVED FIXED
2 years ago
2 years ago

People

(Reporter: markh, Assigned: tcsc)

Tracking

unspecified
Firefox 49
Points:
---
Bug Flags:
firefox-backlog +

Firefox Tracking Flags

(firefox49 fixed)

Details

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment)

(Reporter)

Description

2 years ago
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.
Flags: firefox-backlog+
Priority: -- → P3
(Assignee)

Comment 1

2 years ago
Created attachment 8746088 [details]
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/
Attachment #8746088 - Flags: review?(markh)
(Assignee)

Updated

2 years ago
Assignee: nobody → tchiovoloni
Status: NEW → ASSIGNED
(Reporter)

Comment 2

2 years ago
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(...)
Attachment #8746088 - Flags: review?(markh)
(Assignee)

Comment 3

2 years ago
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/
Attachment #8746088 - Flags: review?(markh)
(Assignee)

Comment 4

2 years ago
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?
(Reporter)

Updated

2 years ago
Attachment #8746088 - Flags: review?(markh) → review+
(Reporter)

Comment 5

2 years ago
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!
(Reporter)

Comment 6

2 years ago
(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.
(Assignee)

Updated

2 years ago
Keywords: checkin-needed
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
Flags: needinfo?(tchiovoloni)
(Assignee)

Comment 9

2 years ago
Ah, crap. 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).
Flags: needinfo?(tchiovoloni)
(Assignee)

Comment 10

2 years ago
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/
Attachment #8746088 - Attachment description: MozReview Request: Bug 1263280 - Dump a list of addons currently active when writing the sync error log r?markh → MozReview Request: Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh
(Reporter)

Comment 11

2 years ago
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...
(Assignee)

Comment 12

2 years ago
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.
(Assignee)

Comment 13

2 years ago
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/
(Assignee)

Updated

2 years ago
Keywords: checkin-needed

Comment 17

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/b02b83d3af40
Status: ASSIGNED → RESOLVED
Last Resolved: 2 years ago
status-firefox49: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 49
You need to log in before you can comment on or make changes to this bug.