Closed Bug 1425987 Opened 2 years ago Closed 2 years ago

Cleanup Sync's use of Log.jsm

Categories

(Firefox :: Sync, enhancement, P2)

enhancement

Tracking

()

RESOLVED FIXED
Firefox 59
Tracking Status
firefox59 --- fixed

People

(Reporter: markh, Assigned: markh)

References

Details

Attachments

(2 files)

Sync uses Log.jsm heavily, but uses it poorly. In particular:

* It uses an ad-hoc system of using prefs to control the log level, but these prefs may be read many times, and don't support the prefs being changed at runtime.

* Log.jsm allows a log's level to be determined by its parent, meaning you can configure the level for a "root" logger once and have all children inherit that level. However, Sync defeats this feature by specifying levels for each individual child log, meaning lots of additional configuration and many many prefs need adjusting to control the log levels.

My solution to this is:

* Have Log.jsm learn how to use preferences to control log levels - it knows if a log has already been configured with a pref so avoids re-reading that pref. It also sets up an observer for the pref so log levels can be changed at runtime.

* Have Sync use this facility for each of the logs it uses.

* Only specify default log levels for 2 "root" loggers, meaning far less preferences need to be set by default, while still allowing users/developers to create new preferences for full, fine-grained control.

These changes will also make bug 1425544 far far simpler - only 2 prefs need to be touched to enable Trace level logging for all Sync logs.
Comment on attachment 8937565 [details]
Bug 1425987 - part 1: Add support to Log.jsm for managing log levels via prefs.

https://reviewboard.mozilla.org/r/208240/#review214308

I think this leaks until shutdown of the pref service, which we should avoid.

If we can use XPCOMUtils.defineLazyPreferenceGetter here that would be preferable, IMO.

::: toolkit/modules/Log.jsm:318
(Diff revision 2)
> +                `preference '${this._levelPrefName}' - ignoring request to ` +
> +                `also use the preference '${prefName}'`);
> +      return;
> +    }
> +    this._levelPrefName = prefName;
> +    Services.prefs.addObserver(prefName, this._observePref.bind(this));

You don't (and can't, actually!) remove this observer. Nor is it added as a weak ref. So AIUI, as long as the process lives, the log object will live, because the pref service holds on to the observer which holds on to the method which is bound to the object. That doesn't seem right to me.

::: toolkit/modules/Log.jsm:327
(Diff revision 2)
> +    if (Services.prefs.getPrefType(data) != Services.prefs.PREF_STRING) {
> +      return;
> +    }
> +    let levelString = Services.prefs.getStringPref(data);

Instead of doing this, just use `getStringPref` but provide a default (ie second arg) of `""` and return if that's the result of the `getStringPref` call?
Attachment #8937565 - Flags: review?(gijskruitbosch+bugs)
Comment on attachment 8937566 [details]
Bug 1425987 - part 2: Cleanup Sync logging by rationalizing preference management.

https://reviewboard.mozilla.org/r/208242/#review214282

I don't love that we have parallel and separate hierarchies of logger settings (which cause issues in the case where they're not the same, e.g. the BookmarkSyncUtils nit below), but I guess we already had this, it's just more obvious now.

On the upside, it makes my patch for bug 1425544 very small (while also fixing the logs for cases like about:sync-log, which my patch ignored), and seems to fix the top offender of bug 1425960 as well!

That said, I have enough small concerns that I'd like to see this patch again.

::: services/sync/modules/browserid_identity.js:35
(Diff revision 2)
>  XPCOMUtils.defineLazyModuleGetter(this, "fxAccounts",
>                                    "resource://gre/modules/FxAccounts.jsm");
>  
>  XPCOMUtils.defineLazyGetter(this, "log", function() {
>    let log = Log.repository.getLogger("Sync.BrowserIDManager");
> -  log.level = Log.Level[Svc.Prefs.get("log.logger.identity")] || Log.Level.Error;
> +  log.manageLevelFromPref(`${PREFS_BRANCH}log.logger.identity`);

It's not clear to me that `${PREFS_BRANCH}` is giving us any value here. Half the loggers just use `services.sync.` directly, which seems clearer and less error prone to me.

::: services/sync/modules/engines.js:59
(Diff revision 2)
>    name = name || "Unnamed";
>    this.name = this.file = name.toLowerCase();
>    this.engine = engine;
>  
> -  this._log = Log.repository.getLogger("Sync.Tracker." + name);
> -  let level = Svc.Prefs.get("log.logger.engine." + this.name, "Debug");
> +  this._log = Log.repository.getLogger(`Sync.Engine.${name}.Tracker`);
> +  this._log.manageLevelFromPref(`${PREFS_BRANCH}log.logger.engine.${this.name}`);

I think this line is unnecessary, since in the absense of a setting it will use the parent logger, which will already be set up to use that preference.

::: services/sync/modules/engines.js:306
(Diff revision 2)
>    name = name || "Unnamed";
>    this.name = name.toLowerCase();
>    this.engine = engine;
>  
> -  this._log = Log.repository.getLogger("Sync.Store." + name);
> -  let level = Svc.Prefs.get("log.logger.engine." + this.name, "Debug");
> +  this._log = Log.repository.getLogger(`Sync.Engine.${name}.Store`);
> +  this._log.manageLevelFromPref(`${PREFS_BRANCH}log.logger.engine.${this.name}`);

Ditto above about this line being unnecessary.

::: services/sync/modules/engines.js:663
(Diff revision 2)
>    this.name = name.toLowerCase();
>    this.service = service;
>  
>    this._notify = Utils.notify("weave:engine:");
>    this._log = Log.repository.getLogger("Sync.Engine." + this.Name);
> -  let level = Svc.Prefs.get("log.logger.engine." + this.name, "Debug");
> +  this._log.manageLevelFromPref(`log.logger.engine.${this.name}`);

This should be `services.sync.log.logger.engine.${this.name}`, no? (e.g. it's missing the pref branch)

::: services/sync/modules/policies.js:674
(Diff revision 2)
> +    // And allow our specific log to have a custom level via a pref.
>      this._log = Log.repository.getLogger("Sync.ErrorHandler");
> -    this._log.level = Log.Level[Svc.Prefs.get("log.logger.service.main")];
> +    this._log.manageLevelFromPref(`${PREFS_BRANCH}log.logger.service.main`);
>  
> -    let root = Log.repository.getLogger("Sync");
> -    root.level = Log.Level[Svc.Prefs.get("log.rootLogger")];
> +    let logs = ["Sync", "Services.Common", "FirefoxAccounts", "Hawk",
> +                "browserwindow.syncui", "BookmarkSyncUtils", "addons.xpi",

I noticed https://searchfox.org/mozilla-central/source/services/common/hawkrequest.js#154 while testing this out.

Can you either add Services.common to this list, or (much preferably) capitalize Common in that file.

::: services/sync/modules/stages/enginesync.js:28
(Diff revision 2)
>   *
>   * This was originally split out of service.js. The API needs lots of love.
>   */
>  this.EngineSynchronizer = function EngineSynchronizer(service) {
>    this._log = Log.repository.getLogger("Sync.Synchronizer");
> -  this._log.level = Log.Level[Svc.Prefs.get("log.logger.synchronizer")];
> +  this._log.manageLevelFromPref(`{PREFS_BRANCH}log.logger.synchronizer`);

Missing `$` to trigger interpolation. As elsewhere I'd prefer just using `services.sync.` explicitly though.

::: services/sync/services-sync.js:67
(Diff revision 2)
> -pref("services.sync.log.logger.authenticator", "Debug");
> -pref("services.sync.log.logger.network.resources", "Debug");
> -pref("services.sync.log.logger.engine.bookmarks", "Debug");
> -pref("services.sync.log.logger.engine.clients", "Debug");
> -pref("services.sync.log.logger.engine.forms", "Debug");
> -pref("services.sync.log.logger.engine.history", "Debug");
> +
> +// Prefs for Sync engines can be controlled globally or per-engine.
> +// We only define the global level here, but manually creating prefs
> +// like "services.sync.log.logger.engine.bookmarks" will control just
> +// that engine.
> +pref("services.sync.log.logger.engine", "Debug");

I don't think we need to give this preference a default setting, do we? It will already be a child of the root logger.

TBH I'd argue against the pref even existing, but it doesn't make *that* much of a difference.

::: toolkit/components/places/PlacesSyncUtils.jsm:1137
(Diff revision 2)
>  });
>  
>  XPCOMUtils.defineLazyGetter(this, "BookmarkSyncLog", () => {
> -  return Log.repository.getLogger("BookmarkSyncUtils");
> +  let log = Log.repository.getLogger("BookmarkSyncUtils");
> +  // Use the same pref as the bookmarks engine.
> +  log.manageLevelFromPref("services.sync.log.logger.engine.bookmarks");

I think this should be a child logger of `Sync`. E.g.  if the root sync logger is the only configured logger, it should inherit that.

As it is it will nominally inherit from bookmarks, but only if that is specified explicitly. If the bookmarks log isn't explicitly specified (which it's not by default), it will inherit from the root logger which is configured to `All`, e.g. this logger will currently have trace logging enabled by default, which is probably not what we want, given that it contains PII. Unless I'm missing something (which I probably am, since if I were correct this would be true without your patch as well, but I'm reasonably confident that it's not... Maybe something to do with appenders?).

Renaming the logger so it inherits from the root sync logger should fix it, e.g. something like `Sync.BookmarkUtils`?
Attachment #8937566 - Flags: review?(tchiovoloni)
(In reply to :Gijs from comment #5)
> https://reviewboard.mozilla.org/r/208240/#review214308
> 
> I think this leaks until shutdown of the pref service, which we should avoid.

It's certainly true that this observer will live as long as the log object does, which in practice means "forever" - however, I don't think that's really a leak any more than the log object itself is a leak.

> If we can use XPCOMUtils.defineLazyPreferenceGetter here that would be
> preferable, IMO.

I don't quite understand how that would help - at the time the function is called we need the preference value, so the "lazy" part of that doesn't seem to help. The fact it also uses a weakreference doesn't seem to help, as it will still need to live as long as the log (IOW, |aObject| would need to be the log object).

> You don't (and can't, actually!) remove this observer. Nor is it added as a
> weak ref. So AIUI, as long as the process lives, the log object will live,
> because the pref service holds on to the observer which holds on to the
> method which is bound to the object. That doesn't seem right to me.

That's true today. There's no way to kill a log object. I agree that's not ideal, but this patch doesn't change that.

> Instead of doing this, just use `getStringPref` but provide a default (ie
> second arg) of `""` and return if that's the result of the `getStringPref`
> call?

That sounds good, thanks - but adding ni? for the above comments.
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to Mark Hammond [:markh] from comment #7)
> There's no way to kill a log object.

I don't really understand. Presumably, if there are no more references to it, it gets GC'd, right? Does Log.jsm somehow keep strong refs to all the instances?

But assuming you're right: That is... terrible. Do we audit this somehow? Like, if we had a thing that created instances that had their own loggers (does sync do this?) then we're just leaking the loggers (and thereby potentially the objects, depending on scoping etc. ) until shutdown, even if we discard / stop using the instances? That's a really bad idea.

> I agree that's not
> ideal, but this patch doesn't change that.

Yeah, I mean, what can I say... I don't actually like Log.jsm. In fact, if it went away tomorrow I think our codebase would be better off. But that's just, like, my opinion, man. ;-)

(and I felt that way before finding out about the potential for leaks. It's an over-engineered thing for "give me debug output" - something we almost never use in production, and we still always run/call/eval all the stuff that's being passed to Log.foo() methods even if the logging itself is a no-op, so we just throw it away, which has perf impact, so yeah.)


Ahem. With my opinions out of the way, if the status quo is that we leak all the things here, then leaking the observer I guess is OK. But please file a followup bug to like, not leak the loggers.
Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(markh)
Yes, strong refs are kept in Log.jsm, and yes, that's not ideal. To be clear, Log.jsm is not my baby :)

While some of this is now moot (see below), I think it's still work mentioning:

Typical usage tends to be a log used as a global in a jsm (or a singleton in a jsm), so until unloading modules is actually useful and something we do, no logs are going to be collected in practice.

It's also true that outside of Sync, most usage arranges for output to be sent to either the browser console or to dump, so it's true that Log.jsm is a much larger hammer than needed in most cases. Sync is somewhat special in that it arranges for log output to be sent to a file, and for the sync team to regularly ask users to attach such logs to bugs - so for Sync, the size of the hammer doesn't seem that outrageous.

tl;dr:

* Other than for Sync, Log.jsm is often the wrong hammer to use.

* I don't think making logs collectable would actually collect any logs in practice.

All that said though, I did some up with a way to sanely use defineLazyPreferenceGetter by checking the pref value in the level getter while  avoiding the need for an observer. Hopefully this addresses your concerns.

Thanks!
Flags: needinfo?(markh)
Comment on attachment 8937565 [details]
Bug 1425987 - part 1: Add support to Log.jsm for managing log levels via prefs.

https://reviewboard.mozilla.org/r/208240/#review214348
Comment on attachment 8937566 [details]
Bug 1425987 - part 2: Cleanup Sync logging by rationalizing preference management.

https://reviewboard.mozilla.org/r/208242/#review214282

Yeah, I don't like the separate hierarchies, but decided against shaving that yak in this bug - all the old pref names still work, it's just that most are no longer necessary.

> I think this line is unnecessary, since in the absense of a setting it will use the parent logger, which will already be set up to use that preference.

ah yes, nice spot!

> I noticed https://searchfox.org/mozilla-central/source/services/common/hawkrequest.js#154 while testing this out.
> 
> Can you either add Services.common to this list, or (much preferably) capitalize Common in that file.

I changed the logger name there, but didn't bother giving it the new manageLevelFromPref treatment.

> I don't think we need to give this preference a default setting, do we? It will already be a child of the root logger.
> 
> TBH I'd argue against the pref even existing, but it doesn't make *that* much of a difference.

As we discussed on IRC, I did it this way to there's an easy/obvious way for users to tweak engine levels without paying the cost of *all* logs being trace (which, eg, causes request and response bodies to be logged). We can always rethink this later if we like.

> I think this should be a child logger of `Sync`. E.g.  if the root sync logger is the only configured logger, it should inherit that.
> 
> As it is it will nominally inherit from bookmarks, but only if that is specified explicitly. If the bookmarks log isn't explicitly specified (which it's not by default), it will inherit from the root logger which is configured to `All`, e.g. this logger will currently have trace logging enabled by default, which is probably not what we want, given that it contains PII. Unless I'm missing something (which I probably am, since if I were correct this would be true without your patch as well, but I'm reasonably confident that it's not... Maybe something to do with appenders?).
> 
> Renaming the logger so it inherits from the root sync logger should fix it, e.g. something like `Sync.BookmarkUtils`?

I ended up making it "Sync.Engine.Bookmarks.BookmarkSyncUtils" so it follows the bookmark engine level.
Comment on attachment 8937565 [details]
Bug 1425987 - part 1: Add support to Log.jsm for managing log levels via prefs.

https://reviewboard.mozilla.org/r/208240/#review214482

Nice. Using the utility function here also has the benefit that if we end up changing prefs enough that we can (and/or want to) reimplement XPCOMUtils.definelazyPreferenceGetter such that it's in native code.

Do we know how many other Log.jsm consumers could now be simplified to use this builtin support instead of doing their own pref monitoring?

::: toolkit/modules/Log.jsm:284
(Diff revision 3)
> +      // pref has a value we use it, otherwise we continue to use the parent.
> +      const lpv = this._levelPrefValue;
> +      if (lpv) {
> +        const levelValue = Log.Level[lpv];
> +        if (levelValue) {
> +          // stash it in _level just incase a future value of the pref is

Nit: here and below "in case".

::: toolkit/modules/Log.jsm:347
(Diff revision 3)
> +                `preference '${this._levelPrefName}' - ignoring request to ` +
> +                `also use the preference '${prefName}'`);
> +      return;
> +    }
> +    this._levelPrefName = prefName;
> +    XPCOMUtils.defineLazyPreferenceGetter(this, "_levelPrefValue", prefName, null);

Fairly sure you don't need the final `null` param.
Attachment #8937565 - Flags: review?(gijskruitbosch+bugs) → review+
Comment on attachment 8937566 [details]
Bug 1425987 - part 2: Cleanup Sync logging by rationalizing preference management.

https://reviewboard.mozilla.org/r/208242/#review214500

This looks good now, thanks!
Attachment #8937566 - Flags: review?(tchiovoloni) → review+
Comment on attachment 8937565 [details]
Bug 1425987 - part 1: Add support to Log.jsm for managing log levels via prefs.

https://reviewboard.mozilla.org/r/208240/#review214482

I can't find any other log consumers that watch prefs or otherwise handle them changing at runtime. There are a few places that could be improved by using this, but it's not clear anyone actually cares - their use of logging is really a debug tool and probably only makes sense while someone is actually working on the code.
Pushed by mhammond@skippinet.com.au:
https://hg.mozilla.org/integration/autoland/rev/ac05441603b1
part 1: Add support to Log.jsm for managing log levels via prefs. r=Gijs
https://hg.mozilla.org/integration/autoland/rev/38ff4596320b
part 2: Cleanup Sync logging by rationalizing preference management. r=tcsc
https://hg.mozilla.org/mozilla-central/rev/ac05441603b1
https://hg.mozilla.org/mozilla-central/rev/38ff4596320b
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 59
You need to log in before you can comment on or make changes to this bug.