1174785 - Add a LogModule replacement for PRLogModuleInfo

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Eric Rahm [:erahm]]

We would like to be able to configure log levels via user prefs at runtime. In order to support this we'll:
 1) Add a new LogModule class to replace PRLogModuleInfo
 2) Add a logging manager that maintains a list of all LogModules
 3) Have the logging manager listen for "logging.*" pref changes

Additionally as a proof of concept we should convert some existing PRLogModuleInfo instances over to LogModule.

Comment 1

[Benjamin Smedberg]

Since we already have this via Log.jsm, can we figure out a way to unify these (JS/C++) rather than have the NSPR/C++ logging continue to be an entirely separate beast from the JS logging libraries?

Comment 2

[Eric Rahm [:erahm]]

Attachment: Part 1: Add LogModule and LogModuleManager

Comment 3

[Eric Rahm [:erahm]]

Attachment: Part 2: Add support for specifying log levels in user prefs

LogModule levels can be specified via user prefs. For example setting the user
pref 'logging.foo' to the integer value 4 would set the log level of the 'foo'
log module to LogLevel::Debug.

Comment 4

[Eric Rahm [:erahm]]

Attachment: Part 3: Add LazLogModule for lazy loading LogModules

Comment 5

[Eric Rahm [:erahm]]

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #1)
> Since we already have this via Log.jsm, can we figure out a way to unify
> these (JS/C++) rather than have the NSPR/C++ logging continue to be an
> entirely separate beast from the JS logging libraries?

I think that's out of scope for what we're trying to do (mainly improve gecko's logging story) and w/ the concern that logging "slows things down" I don't think we're going to want to bridge the js<->cpp gap to check if log levels are enabled etc.

It *would* be interesting to have Log.jsm propagate log levels to the C++ side, so lets say you did:
> Log.repository.getLogger("Loop.Importer.Google").level = Log.Level.Debug;
That would set the pref "logging.Loop.Importer.Google" => 4

But I still think that's outside of the scope of this bug, certainly worth a follow up though.

Comment 6

[Nathan Froyd [:froydnj]]

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #1)
> Since we already have this via Log.jsm, can we figure out a way to unify
> these (JS/C++) rather than have the NSPR/C++ logging continue to be an
> entirely separate beast from the JS logging libraries?

What is "Since we already have this" refer to?  I looked at Log.jsm and I don't see anything pref-related.  Are you talking about the generic facility to twiddle logging levels at runtime?

Comment 7

[Benjamin Smedberg]

Typically the client of Log.jsm will provide the pref name and set the log level from that: http://mxr.mozilla.org/mozilla-central/source/browser/experiments/Experiments.jsm#127

My concern is that at least use the same set of logging level variables, so that we don't end up with a confusing mix: the prefs in this case can be either strings ("Warn", "Info") or numeric values.

I'm disappointed that "improve gecko's logging story" apparently only means the C++ parts of gecko. Are we destined to permanently have a fractured logging story where c++ code uses an entirely different mechanism than the JS code? I'd encourage you to implement Log.jsm in terms of the new c++ backend if necessary to keep them unified. Certainly having C++ call out to JS doesn't make much sense in this context, because of threading.

Comment 8

[Nathan Froyd [:froydnj]]

Comment on attachment 8622581 [details] [diff] [review]
Part 3: Add LazLogModule for lazy loading LogModules

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

Probably want to fix the commit message. ;)

::: xpcom/glue/Logging.h
@@ +104,5 @@
> +
> +  operator LogModule*() {
> +    static LogModule* log = nullptr;
> +    if (!log) {
> +      log = LogModule::CreateOrGetModule(mLogName);

This should be:

static LogModule* log = LogModule::CreateOrGetModule(mLogName);

Comment 9

[Nathan Froyd [:froydnj]]

Comment on attachment 8622578 [details] [diff] [review]
Part 1: Add LogModule and LogModuleManager

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

I'd really like to see some new-style-log-using code before r+'ing all the patches in this bug.

::: xpcom/glue/Logging.cpp
@@ +13,5 @@
> +
> +// TODO(ER): Tune this appropriately from a runtime value.
> +//           Currently there are 251 log modules declared, some of which are
> +//           duplicates. Without duplicates there are 218 declared.
> +const uint32_t kInitialModuleCount = 218;

I wouldn't worry about making this too exact.  Grovel through the code for log modules, round it off to a pretty number, and write a comment saying that we audited all the current log modules + a bit of slop to arrive at the value.

@@ +26,5 @@
> +    //           to cleanup.
> +    static LogModuleManager* manager = nullptr;
> +    if (!manager) {
> +      manager = new LogModuleManager();
> +    }

This should just be:

static LogModuleManager* manager = new LogModuleManager();

return manager;

If you want to clean it up, you could look into something like:

http://mxr.mozilla.org/mozilla-central/source/xpcom/base/ClearOnShutdown.h#15

@@ +57,5 @@
> +      // be. LogModule uses the LogLevel enum class so we must clamp the value
> +      // to a max of Verbose.
> +      PRLogModuleLevel level = std::min(
> +          prModule->level,
> +          static_cast<PRLogModuleLevel>(LogLevel::Verbose));

Paranoia (since NSPR accepts information from environment variables) would dictate clamping the lower bound as well.  Maybe NSPR already does this...paranoia would probably still dictate clamping in both directions.

@@ +67,5 @@
> +    return module;
> +  }
> +
> +  /**
> +   * Sets the level for the given module. Creates it if necessary.

This seems like a weird function to have; what's the rationale for having this separate?  Am I ever going to want to set the log level for a module and not want to have a handle on the log module?

::: xpcom/glue/Logging.h
@@ +51,5 @@
> +   *
> +   * @param aName The name of the module.
> +   * @return A log module for the given name. This may be shared.
> +   */
> +  static LogModule* CreateOrGetModule(const char* aName);

Kinda thinking that if people aren't going to call this directly--because they're using LazyLogModule instead--then we could just call this Get(const char*).  Not entirely sure what the client code is going to look like.

Comment 10

[Nathan Froyd [:froydnj]]

Comment on attachment 8622579 [details] [diff] [review]
Part 2: Add support for specifying log levels in user prefs

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

+1 on the string prefs and we need to get the pref namespacing scheme decided.

::: xpcom/glue/Logging.cpp
@@ +20,5 @@
>  // TODO(ER): Tune this appropriately from a runtime value.
>  //           Currently there are 251 log modules declared, some of which are
>  //           duplicates. Without duplicates there are 218 declared.
>  const uint32_t kInitialModuleCount = 218;
> +const char* const kLoggingPrefPrefix = "logging.";

static const char kLoggingPrefPrefix[] = "logging.";

please.

@@ +82,5 @@
> +
> +      // Check for a user specified level in preferences.
> +      nsCString fullPath(kLoggingPrefPrefix);
> +      fullPath.Append(aName);
> +      GetPrefValue(fullPath.get(), logLevel);

I'm a little skeptical about this exact mechanism, because we have:

logging.$LOG_NAME1
logging.$LOG_NAME2

which is dumping everything under sub-namespaces of "logging".  The more typical route is to have a toplevel pref namespace for a feature ("dom", "layout", "telemetry", etc.) and then stuff appropriate things under that.

@@ +111,5 @@
> +      LogLevel level = LogLevel::Disabled;
> +      GetPrefValue(name.get(), level);
> +      // TODO(ER): There must be a better way of doing this.
> +      SetLogLevel(
> +          nsCString(Substring(name, strlen(kLoggingPrefPrefix))).get(),

NS_LossyConvertUTF16toASCII is a nsCString, so you should be able to call all the normal string methods on it...

@@ +112,5 @@
> +      GetPrefValue(name.get(), level);
> +      // TODO(ER): There must be a better way of doing this.
> +      SetLogLevel(
> +          nsCString(Substring(name, strlen(kLoggingPrefPrefix))).get(),
> +          level);

Ah, here's the "don't care about the log module handle" case.  I don't think explicitly fetching the module via GetModule() or whatever we call it and then calling SetLevel() on that is that bad.

@@ +138,5 @@
>  private:
> +  virtual ~LogModuleManager()
> +  {
> +    // NB: mModules owns all of the log modules, they will get destroyed by
> +    //     it's destructor.

Nit: "its destructor"

@@ +149,5 @@
> +  {
> +#ifdef MOZILLA_INTERNAL_API
> +    int32_t level = 0;
> +    nsresult rv = Preferences::GetInt(aName, &level);
> +    // TODO(ER): Fallback to a string version

Yeah, we need to support string prefs.

Comment 11

[Nathan Froyd [:froydnj]]

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #7)
> Typically the client of Log.jsm will provide the pref name and set the log
> level from that:
> http://mxr.mozilla.org/mozilla-central/source/browser/experiments/
> Experiments.jsm#127

Thanks for the example.

> My concern is that at least use the same set of logging level variables, so
> that we don't end up with a confusing mix: the prefs in this case can be
> either strings ("Warn", "Info") or numeric values.

I think that's reasonable, though Log.jsm appears to have a more extensive set of levels than we settled on for platform.

> I'm disappointed that "improve gecko's logging story" apparently only means
> the C++ parts of gecko. Are we destined to permanently have a fractured
> logging story where c++ code uses an entirely different mechanism than the
> JS code? I'd encourage you to implement Log.jsm in terms of the new c++
> backend if necessary to keep them unified. Certainly having C++ call out to
> JS doesn't make much sense in this context, because of threading.

I'm a little leery of scope-creeping this logging project too much.  The original bug 881389 was, AFAICT, only directed at improving the logging situation for B2G platform people...which is probably a function of B2G platform frustration at the time.

I'll have a look at Log.jsm and see how much we can align.

Comment 12

[Eric Rahm [:erahm]]

Attachment: Part 4: Convert xpcom over to LogModule

An example of converting xpcom over to (Lazy)LogModule.

Comment 13

[Eric Rahm [:erahm]]

Thanks for the feedback, it all makes sense. It sounds like the main thing we need to figure out is pref -> log module mappings.

(In reply to Nathan Froyd [:froydnj] [:nfroyd] from comment #10)
> @@ +82,5 @@
> > +
> > +      // Check for a user specified level in preferences.
> > +      nsCString fullPath(kLoggingPrefPrefix);
> > +      fullPath.Append(aName);
> > +      GetPrefValue(fullPath.get(), logLevel);
> 
> I'm a little skeptical about this exact mechanism, because we have:
> 
> logging.$LOG_NAME1
> logging.$LOG_NAME2
> 
> which is dumping everything under sub-namespaces of "logging".  The more
> typical route is to have a toplevel pref namespace for a feature ("dom",
> "layout", "telemetry", etc.) and then stuff appropriate things under that.

Note: $LOG_NAME1 is arbitrary, so they can be nested.

If we go the route of each logger choosing its own pref we'll need to register individually for all of those prefs which feels a bit heavy handed. Also they'll need to tell us which pref to use, ie:

> LazyLogModule foo(name: "foo", pref: "foo.config.log.level");

Which wouldn't be the end of the world, but it gets a bit weird in that we support sharing log modules. So then we run into what happens if someone does:

> // file_1.cpp
> LazyLogModule foo(name: "foo", pref: "foo.config.log.level");
> 
> // file_2.cpp
> LazyLogModule foo(name: "foo", pref: "foo.log.level");

Which one wins?

And then there's a usability hit, as someone who opens up about:config if all levels are under "logging.", I can type in "logging." and see all configured/configurable levels in one place. Even better imagine an add-on that adds a logging menu that is populated from the pref list, that's not really doable if they're spread out.

> 
> @@ +111,5 @@
> > +      LogLevel level = LogLevel::Disabled;
> > +      GetPrefValue(name.get(), level);
> > +      // TODO(ER): There must be a better way of doing this.
> > +      SetLogLevel(
> > +          nsCString(Substring(name, strlen(kLoggingPrefPrefix))).get(),
> 
> NS_LossyConvertUTF16toASCII is a nsCString, so you should be able to call
> all the normal string methods on it...

Yeah I just don't know what the string methods are (or docs here are pretty sad, or I'm horribly bad at finding thing). Substring returns a DependentCString (or whatever it's called), which doesn't have a |get| method. I just want to do roughly |name.trimleft(prefix).get()|

Comment 14

[Mike Hommey [:glandium]]

As mentioned on irc, xpcom/glue is not the right place for this. More generally, anything that has global singletons should be left out of xpcom/glue. Why? will you ask, well, because the xpcom glue comes in many flavors and is linked essentially everywhere. Even if you avoid those things going in the standalone flavor of the glue, as I originally suggested, you will still have it in everything that links with dependent linkage, which includes cpp unit tests, simple programs, xpcshell, xpcom components (like browsercomps). And here I don't mean they'll happily use the symbol from libxul, I mean they will each have their own, on top of libxul having one. You can imagine all the fun problems that can ensue from this.

Comment 15

[Nathan Froyd [:froydnj]]

Comment on attachment 8623831 [details] [diff] [review]
Part 4: Convert xpcom over to LogModule

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

I think I said this seems reasonable over IRC.  I didn't look closely at every single file.

Comment 16

[Eric Rahm [:erahm]]

This task has gotten complicated enough, I'm going to reduce the scope of this bug to just:

> 1) Add a new LogModule class to replace PRLogModuleInfo
> 2) Add a logging manager that maintains a list of all LogModules
> 
> Additionally as a proof of concept we should convert some existing PRLogModuleInfo instances over to LogModule.

We will do the configurable part as a follow up.

Comment 17

[Eric Rahm [:erahm]]

Attachment: Part 1: Add LogModule, LogModuleManager, and LazyLogModule

The logging interface is moved to xpcom/base, a LogModule wrapper for PR_Log is
added, a thread-safe LogModuleManager is added, and a LazyLogModule class used
to lazily load log modules in a thread-safe manner is added.

Comment 18

[Eric Rahm [:erahm]]

Attachment: Part 2: Convert xpcom over to LogModule

Comment 19

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=cb0a84a7d259

Comment 20

[Nathan Froyd [:froydnj]]

Comment on attachment 8673888 [details] [diff] [review]
Part 1: Add LogModule, LogModuleManager, and LazyLogModule

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

Something in your push is making builds very unhappy, though the LSan problem I note below doesn't seem to show up...

Lots of little comments; r=me with the changes below.

::: xpcom/base/Logging.cpp
@@ +40,5 @@
> +
> +  ~LogModuleManager()
> +  {
> +    // NB: mModules owns all of the log modules, they will get destroyed by
> +    //     it's destructor.

Nit: "its"

@@ +93,5 @@
> +  }
> +
> +  // NB: We intentionally do not register for ClearOnShutdown as that happens
> +  //     before all logging is complete. And, yes, that means we leak, but
> +  //     we're doing that intentionally and the xpcom peer said it was okay.

I think the "...and the xpcom peer said it was okay." is probably redundant, given that it's in the tree.

We probably need to do something to make this LSan-clean.

::: xpcom/base/Logging.h
@@ +13,1 @@
>  #include "mozilla/Assertions.h"

Nit: alphabetical order for mozilla/ headers, please.

@@ +58,5 @@
> +#if !defined(MOZILLA_XPCOMRT_API)
> +  static LogModule* Get(const char* aName);
> +#else
> +  // The abomination that is libxpcomrt gets no logging. File a bug and fix it
> +  // if you care.

We should try to keep editorialization out of our comments.  Maybe:

"For simplicity, libxpcomrt doesn't support logging."

@@ +82,5 @@
> +
> +  LogModule(LogModule&) = delete;
> +  LogModule& operator=(const LogModule&) = delete;
> +
> +  LogLevel mLevel;

Could you make this Atomic<Relaxed>, please?  I've noticed that PRLogModule::level is a source of TSan badness, and I'd like to avoid having to fix those sorts of problems with our framework later.

@@ +123,5 @@
> +  }
> +
> +private:
> +  const char* const mLogName;
> +  Atomic<LogModule*> mLog;

Please make this ReleaseAcquire, since we're essentially doing double-checked locking, and we don't need full sequential consistency here.

Comment 21

[Nathan Froyd [:froydnj]]

Comment on attachment 8673889 [details] [diff] [review]
Part 2: Convert xpcom over to LogModule

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

r=me with the AbstractThread et al issues addressed.

::: xpcom/threads/AbstractThread.cpp
@@ +23,5 @@
>  namespace mozilla {
>  
> +static LazyLogModule sMozPromiseLog("MozPromise");
> +
> +LogModule* GetMozPromiseLog()

Why introduce these functions and the extra level of indirection?  You ought to be able to say:

extern LazyLogModule sMozPromiseLog;

in the header and things should Just Work.

::: xpcom/threads/MozPromise.h
@@ +19,5 @@
>  #include "nsThreadUtils.h"
>  
>  namespace mozilla {
>  
> +extern LogModule* GetMozPromiseLog();

See AbstractThread.cpp comment.

::: xpcom/threads/StateWatching.h
@@ +55,5 @@
>   */
>  
>  namespace mozilla {
>  
> +extern LogModule* GetStateWatchingLog();

See AbstractThread.cpp comment.

::: xpcom/threads/nsTimerImpl.h
@@ +21,5 @@
>  #ifdef MOZ_TASK_TRACER
>  #include "TracedTaskCommon.h"
>  #endif
>  
> +extern mozilla::LogModule* GetTimerLog();

I care less about fixing this up than the AbstractThread.cpp one, but if you wanted to...

Comment 22

[Eric Rahm [:erahm]]

Attachment: Part 0: Use mozilla/StaticPtr.h in signalling

Moving xpcom/glue/Logging.h to xpcom/base/Logging.h causes build failures in
signalling due to include conflicts. Rather than having signalling include
'xpcom/base' directly we can switch it over to using the installed headers
under 'mozilla'.

Comment 23

[Eric Rahm [:erahm]]

Comment on attachment 8674420 [details] [diff] [review]
Part 0: Use mozilla/StaticPtr.h in signalling

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

r+ from jesup via IRC.

Comment 24

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=92871e32184e

Comment 25

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ba63c8cb3134

Comment 26

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=472a09e30476

Comment 27

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9f9cd3e3f403

Comment 28

[Eric Rahm [:erahm]]

(In reply to Eric Rahm [:erahm] from comment #26)
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=472a09e30476

This looked good, but needed a rebase to get the android reftests run, which is:

> https://treeherder.mozilla.org/#/jobs?repo=try&revision=9f9cd3e3f403

If this looks good, as long as there is no objection to landing bug 1215629 in the next day we should be good to go.

Comment 29

[Eric Rahm [:erahm]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/fd36ee40d1227eb0f7ec0a791f8860364518f325
Bug 1174785 - Part 0: Use mozilla/StaticPtr.h in signaling. r=jesup

https://hg.mozilla.org/integration/mozilla-inbound/rev/342c95afb454a19b82bbfebdef8bd289cac157ea
Bug 1174785 - Part 1: Add LogModule, LogModuleManager, and LazyLogModule. r=froydnj

https://hg.mozilla.org/integration/mozilla-inbound/rev/f9cf413cb3da8c191c2f1ba34b605aa73b2a8e48
Bug 1174785 - Part 2: Convert xpcom over to LogModule. r=froydnj

Comment 30

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/fd36ee40d122
https://hg.mozilla.org/mozilla-central/rev/342c95afb454
https://hg.mozilla.org/mozilla-central/rev/f9cf413cb3da