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.

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?

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.

(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.

(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?

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 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 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 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.

(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.

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

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()|

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 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.

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.

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 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 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...

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 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.

(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.

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

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