This is a spinoff from bug 1174785, more discussion about this feature can be found in that bug. Goal: Support changing log levels at runtime. Usage: 1) User sets "logging.Foo" pref to a string: "Verbose" or an integer: 5 2) The "Foo" log module will now emit up to LogLevel::Verbose messages Limitations: Only loggers that have switched over to the LogModule interface can benefit from this change.

Adds support for changing log levels at runtime via 'logging.*' preferences. Note: currently this only works if a dummy value is provided fo the NSPR_LOG_MODULES env var. This is due to a bug/limitation in NSPR logging. Bug 1174972 will address this limitation.

Comment on attachment 8700224 [details] [diff] [review] Support dynamically setting log levels at runtime via prefs Review of attachment 8700224 [details] [diff] [review]: ----------------------------------------------------------------- I have some questions. ::: xpcom/base/LogModulePrefWatcher.cpp @@ +29,5 @@ > + > + if (Preferences::GetInt(aName, &prefLevel) == NS_OK) { > + logLevel = ToLogLevel(prefLevel); > + } else if (Preferences::GetCString(aName, &prefStr) == NS_OK) { > + if (prefStr.EqualsLiteral("Error")) { For convenience, we should make these comparisons case-insensitive. @@ +64,5 @@ > + NS_LossyConvertUTF16toASCII prefName(aData); > + LogLevel level = GetPrefValue(prefName.get()); > + nsCString logName(Substring(prefName, strlen(kLoggingPrefPrefix))); > + > + LogModule::Get(logName.get())->SetLevel(level); Maybe just: LogModule::Get(&prefName[strlen(kLoggingPrefPrefix))->SetLevel(...); Is that too clever? Alternatively: nsDependentCString(prefName, strlen(kLoggingPrefPrefix); works better, I think (less memory allocation, assuming I understand our string code). ::: xpcom/base/LogModulePrefWatcher.h @@ +27,5 @@ > + > + /** > + * Starts observing pref changes. > + */ > + void Init(); If Init() is going to be infallible, we might as well move Init()'s work into the constructor. Or we might set things up with a static InitForLog() method, so that people aren't creating temporary objects in their code. Are we only supposed to have one pref watcher for all time? Or one pref watcher per LogModule? The code says the former, but the API suggests the latter. When do pref watchers get created and how do they work if preferences aren't up and running? Or, alternatively, how does this work if the observer is registered after the preferences are already set--the observer won't get called then...?

(In reply to Nathan Froyd [:froydnj] from comment #2) > Comment on attachment 8700224 [details] [diff] [review] > Support dynamically setting log levels at runtime via prefs > > Review of attachment 8700224 [details] [diff] [review]: > ----------------------------------------------------------------- > > I have some questions. > > ::: xpcom/base/LogModulePrefWatcher.cpp > @@ +29,5 @@ > > + > > + if (Preferences::GetInt(aName, &prefLevel) == NS_OK) { > > + logLevel = ToLogLevel(prefLevel); > > + } else if (Preferences::GetCString(aName, &prefStr) == NS_OK) { > > + if (prefStr.EqualsLiteral("Error")) { > > For convenience, we should make these comparisons case-insensitive. Sure. > > @@ +64,5 @@ > > + NS_LossyConvertUTF16toASCII prefName(aData); > > + LogLevel level = GetPrefValue(prefName.get()); > > + nsCString logName(Substring(prefName, strlen(kLoggingPrefPrefix))); > > + > > + LogModule::Get(logName.get())->SetLevel(level); > > Maybe just: > > LogModule::Get(&prefName[strlen(kLoggingPrefPrefix))->SetLevel(...); > > Is that too clever? > > Alternatively: > > nsDependentCString(prefName, strlen(kLoggingPrefPrefix); > > works better, I think (less memory allocation, assuming I understand our > string code). > Sounds good. > ::: xpcom/base/LogModulePrefWatcher.h > @@ +27,5 @@ > > + > > + /** > > + * Starts observing pref changes. > > + */ > > + void Init(); > > If Init() is going to be infallible, we might as well move Init()'s work > into the constructor. Or we might set things up with a static InitForLog() > method, so that people aren't creating temporary objects in their code. Yes this seems better, I had the registration code in the ctor originally, but that seemed sketchy (registering a ref counted thing in its ctor). I'll switch to a static function. > Are we only supposed to have one pref watcher for all time? Or one pref > watcher per LogModule? The code says the former, but the API suggests the > latter. One pref watcher for all time. > When do pref watchers get created and how do they work if preferences aren't > up and running? Or, alternatively, how does this work if the observer is > registered after the preferences are already set--the observer won't get > called then...? Registering in nsMemoryReporterManager::Init registers early enough that the prefs haven't been read yet, so the pref watcher gets notified upon initialization.

Adds support for changing log levels at runtime via 'logging.*' preferences.

Comment on attachment 8700723 [details] [diff] [review] Support dynamically setting log levels at runtime via prefs Review of attachment 8700723 [details] [diff] [review]: ----------------------------------------------------------------- Thanks for the explanations. ::: xpcom/base/nsMemoryReporterManager.cpp @@ +1496,5 @@ > nsMemoryInfoDumper::Initialize(); > #endif > > + // Listen for changes to log levels. > + LogModulePrefWatcher::RegisterPrefWatcher(); Where is the enclosing function getting called from, and can we just move this call into the caller (or farther up the call chain, even) so we're not burying the initialization here? Also, we need a comment describing why we're initializing things in *this* particular place, since the dynamic-ness of this requires that the pref watcher be initialized at a particular place.

(In reply to Nathan Froyd [:froydnj] from comment #5) > Comment on attachment 8700723 [details] [diff] [review] > Support dynamically setting log levels at runtime via prefs > > Review of attachment 8700723 [details] [diff] [review]: > ----------------------------------------------------------------- > > Thanks for the explanations. > > ::: xpcom/base/nsMemoryReporterManager.cpp > @@ +1496,5 @@ > > nsMemoryInfoDumper::Initialize(); > > #endif > > > > + // Listen for changes to log levels. > > + LogModulePrefWatcher::RegisterPrefWatcher(); > > Where is the enclosing function getting called from, and can we just move > this call into the caller (or farther up the call chain, even) so we're not > burying the initialization here? The stack is rather large, roughly it comes down to nsComponentManagerImpl::Init reading a manifest [1] which pokes something down the line that registers a memory reporter. So perhaps nsComponentManagerImpl is a more appropriate location. > Also, we need a comment describing why we're initializing things in *this* > particular place, since the dynamic-ness of this requires that the pref > watcher be initialized at a particular place. Sure, I'll add a note to the chosen location. [1] https://dxr.mozilla.org/mozilla-central/rev/388bdc46ba51ee31da8b8abe977e0ca38d117434/xpcom/components/nsComponentManager.cpp#446

This moves registration to nsComponentManagerImpl, adds loading of existing prefs to support e10s (and avoid timing issues of registering at the right time).

Comment on attachment 8701260 [details] [diff] [review] Support dynamically setting log levels at runtime via prefs Review of attachment 8701260 [details] [diff] [review]: ----------------------------------------------------------------- ::: xpcom/base/LogModulePrefWatcher.cpp @@ +53,5 @@ > +{ > + uint32_t count; > + char** names; > + nsresult rv = Preferences::GetRootBranch()-> > + GetChildList(kLoggingPrefPrefix, &count, &names); Pretty sure you have to free |names| and its contents once you're done with it. ::: xpcom/components/nsComponentManager.cpp @@ +451,5 @@ > RegisterWeakMemoryReporter(this); > + > + // NB: The logging pref watcher needs to be registered late enough in startup > + // that it's okay to use the pref system. This location meets that > + // requirement. Why can't we start it earlier...like after the pref system starts up? I'm still not convinced that we want to bury this inside the component manager.

(In reply to Nathan Froyd [:froydnj] from comment #8) > Comment on attachment 8701260 [details] [diff] [review] > Support dynamically setting log levels at runtime via prefs > > Review of attachment 8701260 [details] [diff] [review]: > ----------------------------------------------------------------- > > ::: xpcom/base/LogModulePrefWatcher.cpp > @@ +53,5 @@ > > +{ > > + uint32_t count; > > + char** names; > > + nsresult rv = Preferences::GetRootBranch()-> > > + GetChildList(kLoggingPrefPrefix, &count, &names); > > Pretty sure you have to free |names| and its contents once you're done with > it. Oh dear, you are absolutely correct. > ::: xpcom/components/nsComponentManager.cpp > @@ +451,5 @@ > > RegisterWeakMemoryReporter(this); > > + > > + // NB: The logging pref watcher needs to be registered late enough in startup > > + // that it's okay to use the pref system. This location meets that > > + // requirement. > > Why can't we start it earlier...like after the pref system starts up? I'm > still not convinced that we want to bury this inside the component manager. Lets just move this into LogModuleManager's init. Even if we register too early, we'll get pref updates once they're loaded. For logging that needs to be done during startup prior to the profile being loaded we can still rely on NSPR_LOG_MODULES.

(In reply to Eric Rahm [:erahm] from comment #9) > (In reply to Nathan Froyd [:froydnj] from comment #8) > > Why can't we start it earlier...like after the pref system starts up? I'm > > still not convinced that we want to bury this inside the component manager. > > Lets just move this into LogModuleManager's init. Even if we register too > early, we'll get pref updates once they're loaded. For logging that needs to > be done during startup prior to the profile being loaded we can still rely > on NSPR_LOG_MODULES. Nathan and I discussed this over IRC. It comes down to a few issues: 1) The pref system needs to only be touched on the main thread 2) The pref system is not loaded at all (profile or not) when LogModuleManager is setup 3) The pref system is registered as a component and setup via registering a CID and all that jazz [1] 4) We want to register ASAP after the pref system is setup so that log modules setup via prefs are enabled So in conclusion, without modifying the pref system [2] to add either a notification when it's initialized or just initialize the LogModulePrefWatcher internally, registering after component manager initialization makes the most sense. I will update the comment to make this a bit more clear. [1] https://dxr.mozilla.org/mozilla-central/rev/9d6ffc7a08b6b47056eefe1e652710a3849adbf7/modules/libpref/nsPrefsFactory.cpp#13-14 [2] The general consensus is that changes to the pref system are frowned upon.

Updates per code review. Properly freeing the names array now and the comment for why we register during component manager initialization has been updated to make the reasoning a bit more clear.

Comment on attachment 8704791 [details] [diff] [review] Support dynamically setting log levels at runtime via prefs Review of attachment 8704791 [details] [diff] [review]: ----------------------------------------------------------------- ::: xpcom/components/nsComponentManager.cpp @@ +451,5 @@ > RegisterWeakMemoryReporter(this); > + > + // NB: The logging pref watcher needs to be registered late enough in startup > + // that it's okay to use the pref system, but also as soon as possible so > + // that log modules enabled via prefs are turned on as early as possible. Maybe add: "We can't initialize the pref watcher when the log module manager is initialized, as a number of things attempt to start logging before the preferences system is initialized." @@ +453,5 @@ > + // NB: The logging pref watcher needs to be registered late enough in startup > + // that it's okay to use the pref system, but also as soon as possible so > + // that log modules enabled via prefs are turned on as early as possible. > + // > + // The preference system is registered as a component so at this point during Nit: "pref system" or "preference system"; pick one and be consistent. Bonus points for being consistent with "pref watcher" and "prefs", too.

https://hg.mozilla.org/integration/mozilla-inbound/rev/57af526c36540febcc4abd173e84468ed3050ed2 Bug 1233881 - Support dynamically setting log levels at runtime via prefs. r=froydnj

\o/ This is probably worth a dev-platform post. It might be worth documenting somewhere on MDN, too. https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/Logging is about NSPR logging, but I guess that's not appropriate given that we're now separate from NSPR logging?

(In reply to Nicholas Nethercote [:njn] from comment #16) > \o/ > > This is probably worth a dev-platform post. > > It might be worth documenting somewhere on MDN, too. > https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/ > Logging is about NSPR logging, but I guess that's not appropriate given that > we're now separate from NSPR logging? I'll add separate docs, a dev-platform post will come once bug 1174972 lands.