1131410 - Extract Sync's log management so it can be reused by the Reading List back-end

Status: RESOLVED FIXED

(Cloud Services :: Firefox: Common, defect)

Description

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

The sync logs are vital for diagnosing Sync related issues, so we should ensure reading-list has the same capability.  We should just rip the sync code out where it can be reused in this context, and reuse about:sync-log

Comment 1

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Attachment: 0001-Bug-1131410-Extract-sync-s-log-management-so-it-can-.patch

As described on the packet!

Comment 2

[Drew Willcoxon :adw]

Comment on attachment 8563247 [details] [diff] [review]
0001-Bug-1131410-Extract-sync-s-log-management-so-it-can-.patch

Review of attachment 8563247 [details] [diff] [review]:
-----------------------------------------------------------------

Seems OK to me!

If I were writing a logging system from scratch and had the requirement of being able to aggregate multiple logs together, I'd probably try to avoid creating a special LogManager type and would instead try to make one Log be able to pipe its messages to any other.  Then when I needed to aggregate many logs into one, I'd make a new Log and pipe all my other logs into it.

::: services/common/logmanager.js
@@ +1,1 @@
> +/* This Source Code Form is subject to the terms of the Mozilla Public

This filename doesn't follow desktop JSM naming conventions, but I recognize that this is in services/.

@@ +29,5 @@
> +// both Sync and Reading-list.
> +// However, different instances have different pref branches, so we need to
> +// handle when one pref branch says "Debug" and the other says "Error"
> +// So we (a) keep singleton console and dump appenders and (b) keep track
> +// of the minimum (ie, most verbose) level and use that.

Makes sense I think!

@@ +112,5 @@
> +        log.addAppender(appender);
> +      }
> +    }
> +    // and use the first specified log as *our* log.
> +    // XXX - is this OK?

Along the lines of what I said above, my first thought would be to create a new log for the manager and route the messages of all the corresponding "sub-logs" through it.  Just my first thought, and without knowing really much at all about Sync logging.

Comment 3

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

(In reply to Drew Willcoxon :adw from comment #2)
> Along the lines of what I said above, my first thought would be to create a
> new log for the manager and route the messages of all the corresponding
> "sub-logs" through it.  Just my first thought, and without knowing really
> much at all about Sync logging.

Sync logging isn't special - it's really just Log.jsm semantics here.  I'm not really clear what you mean though.

The Log.jsm model is that a single log can have many "appenders" - it's expected that a single log can route messages to multiple places.  It also has the concept of a log hierarchy, but that's based on log names, and we don't want to constrain the log names available to be used.

So, what we *could* do is have our own custom appender and add that to each of the logs. This appender could collect stuff from the individual logs and "pipe" it to a new log we've created, but the main drawback is that this would lose the log name from the output - or we'd also need a custom formatter etc - and I think that would *still* leave us with the same basic problems (ie, there's exactly 1 "dump" device, and having multiple dump appenders sourcing stuff from the same log will end up with messages logged multiple times.  IMO the DumpAppender should be a singleton in Log.jsm)

Another solution would be to dictate the log name used by, eg, FxAccounts.  Then we could have completely different logs from FxA when used in a Sync context, and another log when used in a RL context.  However, FxA is effectively a singleton - the exact same instance is used by both (and, eg, it listens to observer notifications and takes actions for *all* consumers) - the FxA user state is global, not per service - so this doesn't work either.

So unless I misunderstand your suggestion, I can only agree it somewhat sucks but can't see a better answer.

Comment 4

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Comment on attachment 8563247 [details] [diff] [review]
0001-Bug-1131410-Extract-sync-s-log-management-so-it-can-.patch

Review of attachment 8563247 [details] [diff] [review]:
-----------------------------------------------------------------

Discussed on IRC. Basically: 
* Yep, that'll do.
* Drew's grouping idea good, but IMO not worth it here (ie, do in Log.jsm eventually).
* Main-thread I/O bad.

Comment 5

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Attachment: 0001-Bug-1131410-Extract-sync-s-log-management-so-it-can-.patch

This version has no main-thread IO \o/.  That did require some changes to the existing tests as they assumed the log writing happened quickly enough whereas now it's quite a bit slower than before (which is just the price we pay for passing all the data to the worker thread and having the IO happen there).

I think it's ready for review, but another sanity check can't hurt.

Comment 6

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Comment on attachment 8565838 [details] [diff] [review]
0001-Bug-1131410-Extract-sync-s-log-management-so-it-can-.patch

I might as well request review now while still waiting for rnewman's feedback. This bug needs to land before the reading list "scheduler" and before the browser UI changes, so (assuming r+) I'll go ahead and land this before rnewman's feedback if necessary (but I'll put off landing until I really need to land those other bugs)

Comment 7

[Richard Newman [:rnewman]]

Sorry for the delay; each time I've come back to this patch, it's required more brain than I've had available!

(Long week.)

Comment 8

[Drew Willcoxon :adw]

Comment on attachment 8565838 [details] [diff] [review]
0001-Bug-1131410-Extract-sync-s-log-management-so-it-can-.patch

Review of attachment 8565838 [details] [diff] [review]:
-----------------------------------------------------------------

As you know I'm not very familiar with Log.jsm so I feel my comments are pretty superficial.  Am I even allowed to r+ stuff in services/? :-)  Richard's feedback even after this lands would be great.

::: services/common/logmanager.js
@@ +13,5 @@
> +  'resource://gre/modules/FileUtils.jsm');
> +XPCOMUtils.defineLazyModuleGetter(this, 'Log',
> +  'resource://gre/modules/Log.jsm');
> +XPCOMUtils.defineLazyModuleGetter(this, 'Task',
> +  'resource://gre/modules/Task.jsm');

Again, it doesn't make sense to lazy-load Task.jsm since it'll be immediately imported when the file is loaded since you're using Task.async to define methods.

@@ +39,5 @@
> +
> +// Singletons used by each instance.
> +let formatter;
> +let dumpAppender;
> +let consoleAppender;

Nit: My same G prefixes nit from the other bug.

@@ +169,5 @@
> +      binaryStream.close();
> +      yield output.close();
> +    }
> +    this._log.trace("finished copy to", outputFile.path);
> +    return (yield OS.File.stat(outputFile.path)).lastModificationDate;

Is the extra I/O of statting the file really worth it?  It looks like you're just logging the date, and returning new Date() would work just as well.  How often do you expect _copyStreamToFile to be called?

@@ +179,5 @@
> +   * Returns a promise that resolves on completion or rejects if the file could
> +   * not be written.
> +   */
> +  resetFileLog(reason) {
> +    return new Promise((resolve, reject) => {

This whole method would be nicer to read and write if it were:

resetFileLog: Task.async(...

right?

@@ +234,5 @@
> +              resolve();
> +            }
> +          );
> +        } else {
> +          resolve();

An early return in this case would make this easier to read, too.

::: services/common/tests/unit/test_logmanager.js
@@ +22,5 @@
> +  return [capps[0], dapps[0], fapps];
> +}
> +
> +// Test that the correct thing happens when no prefs exist for the log manager.
> +add_test(function test_noPrefs() {

Why no add_task for all of these?  IIRC you can pass non-generator functions to add_task and it'll work.

@@ +42,5 @@
> +// Test that changes to the prefs used by the log manager are updated dynamically.
> +add_test(function test_PrefChanges() {
> +  Services.prefs.setCharPref("log-manager.test.log.appender.console", "Trace");
> +  Services.prefs.setCharPref("log-manager.test.log.appender.dump", "Trace");
> +  Services.prefs.setCharPref("log-manager.test.log.appender.file.level", "Trace");

IMO all these prefs should be removed when the test ends.  You could define a setPref helper that calls do_register_cleanup at the same time.

Comment 9

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Attachment: 0001-Bug-1131410-Extract-sync-s-log-management-so-it-can-.patch

(In reply to Drew Willcoxon :adw from comment #8)
> Richard's feedback even after this lands would be great.

Agreed - let's give him 1 more day ;)

> Again, it doesn't make sense to lazy-load Task.jsm since it'll be
> immediately imported when the file is loaded since you're using Task.async
> to define methods.

Fixed.

> @@ +39,5 @@
> > +
> > +// Singletons used by each instance.
> > +let formatter;
> > +let dumpAppender;
> > +let consoleAppender;
> 
> Nit: My same G prefixes nit from the other bug.

I hate the prefixes too and don't really think they would make this module easier to understand, so I skipped this.

> Is the extra I/O of statting the file really worth it?

I think you're correct - I removed this.

> resetFileLog: Task.async(...
> 
> right?

Yep, done.

> Why no add_task for all of these?  IIRC you can pass non-generator functions
> to add_task and it'll work.

Sure, why not! :)

> IMO all these prefs should be removed when the test ends.  You could define
> a setPref helper that calls do_register_cleanup at the same time.

I didn't do this as xpcshell never shares a profile with another test, and in a recent patch Gavin asked me to remove such a cleanup for this reason when reviewing a patch :)

Carrying Drew's r+ forward but requesting it from rnewman, but I'll land without that if he's too busy to get to this.

Comment 10

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

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

Comment 11

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

ack - I pushed an earlier version of this patch.  I'll push a followup soon.

Comment 12

[Richard Newman [:rnewman]]

Comment on attachment 8567789 [details] [diff] [review]
0001-Bug-1131410-Extract-sync-s-log-management-so-it-can-.patch

Review of attachment 8567789 [details] [diff] [review]:
-----------------------------------------------------------------

Using "sync-error-" will cause new errors to be hidden underneath old ones in about:sync-log (descending sort), right? It also breaks the error/success categorization. I think we want all error logs to be together, not all sync logs.

Consider error-sync-, success-sync- instead.

If about:sync-logs and success and failure log capture work with this change, rock on.

::: services/common/logmanager.js
@@ +1,4 @@
> +/* This Source Code Form is subject to the terms of the Mozilla Public
> + * License, v. 2.0. If a copy of the MPL was not distributed with this
> + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
> +

Nit: if this is new code, use strict.

@@ +5,5 @@
> +const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
> +
> +Cu.import("resource://gre/modules/XPCOMUtils.jsm");
> +XPCOMUtils.defineLazyModuleGetter(this, 'Services',
> +  'resource://gre/modules/Services.jsm');

Nit: double quotes.

@@ +7,5 @@
> +Cu.import("resource://gre/modules/XPCOMUtils.jsm");
> +XPCOMUtils.defineLazyModuleGetter(this, 'Services',
> +  'resource://gre/modules/Services.jsm');
> +XPCOMUtils.defineLazyModuleGetter(this, 'Preferences',
> +  'resource://gre/modules/Preferences.jsm');

There's no value in this being lazy, is there? Is anyone going to import this module without constructing a LogManager?

@@ +26,5 @@
> +const DEFAULT_MAX_ERROR_AGE = 20 * 24 * 60 * 60; // 20 days
> +
> +// "shared" logs (ie, where the same log name is used by multiple LogManager
> +// instances) are a fact of life here - eg, FirefoxAccounts logs are used by
> +// both Sync and Reading-list.

Nit: Reading List. Make life easier on greppers :)

@@ +101,5 @@
> +    this._observeDumpPref = setupAppender(dumpAppender, "log.appender.dump", Log.Level.Error, true);
> +
> +    // The file appender doesn't get the special singleton behaviour.
> +    let fapp = this._fileAppender = new Log.StorageStreamAppender(formatter);
> +    // the stream gets a default of Debug as the user must go out of there way

s/there/their

@@ +168,5 @@
> +        yield output.write(new Uint8Array(chunk));
> +      }
> +    } finally {
> +      inputStream.close();
> +      binaryStream.close();

If I'm reading nsBinaryStream.cpp correctly, closing the BIS will close its inner stream for you, just as Java's streams do.

Consider wrapping this in an exception handler?

Comment 13

[Richard Newman [:rnewman]]

(In reply to Mark Hammond [:markh] from comment #9)

> > Nit: My same G prefixes nit from the other bug.
> 
> I hate the prefixes too and don't really think they would make this module
> easier to understand, so I skipped this.

FWIW, current style (definitely for this module, and as I understand for all new code and most other code, too): no aFoo, gBar.

Comment 14

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

https://hg.mozilla.org/mozilla-central/rev/37a3d196e63f

Comment 15

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Landed with what I *meant* to land, plus all rnewman's comments addressed.

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

Try at https://treeherder.mozilla.org/#/jobs?repo=try&revision=e9dbcd29c1fe

Comment 16

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

https://hg.mozilla.org/mozilla-central/rev/0e91c57a3ce6

Comment 17

[Jared Wein [:jaws] (please needinfo? me)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/214e71c08482
https://hg.mozilla.org/releases/mozilla-aurora/rev/312551e07500