Rather than a custom module we should just use log4moz once it moves.

It's now Log.jsm (http://dxr.mozilla.org/mozilla-central/source/toolkit/modules/Log.jsm), and yes.

I'd like to have a go at writing a patch for this one. Which tests out of the test suite do you recommend I run to verify that the changes to the Addons Manager haven't caused disturbance? Cheers!

First attempt at a patch for this -- feedback very welcome. I tested this by running ./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js to put the Addon Manager through its paces. I got a result of Passed: 166 Failed: 0 Todo: 0. The logging messages are showing up in the terminal window during Mochitest testing and in the Browser Console in the Javascript (gold) channel. Anything that needs changing, anything that needs doing re. unit tests etc. just let me know. Thanks!

Thanks for taking this on. We don't have automated tests for these log messages, so we can only manually check that the messages appear OK in console output and that the automated tests don't break on the existing functional checks. Aside from the browser mochitests, the add-on manager is also extensively covered by xpcshell tests; you can run those with ./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell If you have further questions you can also ask on Mozilla's IRC server (see https://wiki.mozilla.org/IRC); I'm 'irving', usually available in the #perf channel; Blair ('unfocused' on IRC) and Dave ('mossop' on IRC) are the tech leads for this part of the code base and can also help you if I'm not around.

Comment on attachment 8356147 [details] [diff] [review] bug-661982-fix.patch Review of attachment 8356147 [details] [diff] [review]: ----------------------------------------------------------------- Aside from the use in AddonManager.jsm, we'd like to remove all the other uses. They're all in the same directory (toolkit/mozapps/extensions). The patch should also include removing AddonLogging.jsm from the moz.build file and removing the file itself. AddonRepository.jsm AddonRepository_SQLiteMigrator.jsm AddonUpdateChecker.jsm DeferredSave.jsm PluginProvider.jsm XPIProvider.jsm XPIProviderUtils.js amWebInstallListener.js ::: toolkit/mozapps/extensions/AddonManager.jsm @@ +97,5 @@ > +// Utility helper functions for outputting exceptions and/or messages > +// to the logger. > +function LOG (aMessage) { > + logger.debug (aMessage); > +} I'll defer to Blair and Dave if they disagree, but I would prefer to see a global replace of LOG() with logger.debug() rather than declaring a wrapper function, and similarly for the other log levels. @@ +103,5 @@ > +function WARN(aMessage) { > + logger.warn(aMessage); > +} > + > +function WARN(aMessage, aException) { JavaScript doesn't do parameter overloading like C++; this just discards the definition of WARN(aMessage) and replaces it with a definition of WARN(aMessage, aException) - which works just fine, because when the caller omits a parameter it defaults to 'undefined'

(In reply to :Irving Reid from comment #6) > I would prefer to see a > global replace of LOG() with logger.debug() rather than declaring a wrapper > function, and similarly for the other log levels. +1

Cheers Irving, and thanks for your help on this! I'm quite new to Javascript. Thanks for the advice about the overloading which is very helpful, I wasn't aware of that. OK here is my second attempt. Removes file: AddonLogging.jsm Edits files: moz.build in toolkit/mozapps/extensions AddonManager.jsm AddonRepository.jsm AddonRepository_SQLiteMigrator.jsm AddonUpdateChecker.jsm DeferredSave.jsm PluginProvider.jsm XPIProvider.jsm XPIProviderUtils.js amWebInstallListener.js I made and ran a build, and I checked the messages were coming up in the terminal window std out and in the Javascript area of the Browser Console. Here are my test results: ./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell Passed: 147 Failed: 0 Todo: 0 Retried: 1 ./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js Passed: 166 Failed: 0 Todo: 0 I've had a go at using the object orientated features when working on DeferredSave.jsm and XPIProvider.jsm, advice very welcome. Feedback and suggestions for improvement much appreciated. Thanks!

Correction -- removing stray comment on line 58 of DeferredSave.jsm -- everything else in the patch is the same. Thanks!

Comment on attachment 8357121 [details] [diff] [review] bug-661982-fix.patch Review of attachment 8357121 [details] [diff] [review]: ----------------------------------------------------------------- I'm not a peer for the toolkit module, so I can't grant a final review approval for this patch; once it's ready to go we should request review from :mossop or :unfocused. That said, this is coming along well; again, thanks for taking it on. ::: toolkit/mozapps/extensions/AddonManager.jsm @@ +91,5 @@ > +let formatter = new Log.BasicFormatter(); > +// Set logger to append to the Javascript section of the Browser Console > +logger.addAppender(new Log.ConsoleAppender(formatter)); > +// Set logger to also append to standard out > +logger.addAppender(new Log.DumpAppender(formatter)); Log.jsm is like Java's log4j and others, in that there is an implicit hierarchy of loggers created by the path of dot-separated names. This means we can create and configure a logger for "addons", and set the appenders up once on that logger; then all the modules under addons ("addons.manager", "addons.xpi", etc.) don't need to configure their own formatters and appenders - I tested this out on top of your patch and it works great. Here's the difference in how the logger is set up: --- a/toolkit/mozapps/extensions/AddonManager.jsm +++ b/toolkit/mozapps/extensions/AddonManager.jsm @@ -81,23 +81,27 @@ const CATEGORY_PROVIDER_MODULE = "addon- const DEFAULT_PROVIDERS = [ "resource://gre/modules/XPIProvider.jsm", "resource://gre/modules/LightweightThemeManager.jsm" ]; Cu.import("resource://gre/modules/Log.jsm"); const LOGGER_ID = "addons.manager"; +// Configure a logger at the 'addons' level to format and append +// messages for all the modules under addons.* +let parentLogger = Log.repository.getLogger("addons"); +let formatter = new Log.BasicFormatter(); +// Set logger to append to the Javascript section of the Browser Console +parentLogger.addAppender(new Log.ConsoleAppender(formatter)); +// Set logger to also append to standard out +parentLogger.addAppender(new Log.DumpAppender(formatter)); + // Create a new logger for use by the Addons Manager let logger = Log.repository.getLogger(LOGGER_ID); -let formatter = new Log.BasicFormatter(); -// Set logger to append to the Javascript section of the Browser Console -logger.addAppender(new Log.ConsoleAppender(formatter)); -// Set logger to also append to standard out -logger.addAppender(new Log.DumpAppender(formatter)); /** * Calls a callback method consuming any thrown exception. Any parameters after * the callback parameter will be passed to the callback. * * @param aCallback * The callback method to call */ The other nice thing about this is that now it's easier to copy the implementation of logging control via the "extensions.logging.enabled" preference from AddonLogging.jsm to here, so that we preserve the ability to enable/disable messages at run time. Eventually bug 956817 will provide a general solution, but until then this patch should include the control that was previously implemented in AddonLogging.jsm. The basic behaviour I think we want is: if the "extensions.logging.enabled" preference is missing or 'false', messages at the WARNING and higher severity should be logged to the JS console and standard error if "extensions.logging.enabled" is set to 'true', messages at DEBUG and higher should go to JS console and standard error. ::: toolkit/mozapps/extensions/AddonRepository.jsm @@ +66,2 @@ > > +// Create a new logger for use by the Addons Repository Please remove trailing white space on the end of this line ::: toolkit/mozapps/extensions/AddonRepository_SQLiteMigrator.jsm @@ +30,2 @@ > > +// Create a new logger for use by the Addons Repository SQL Migrator Please remove trailing white space at the end of this line @@ +33,5 @@ > +let formatter = new Log.BasicFormatter(); > +// Set logger to append to the Javascript section of the Browser Console > +logger.addAppender(new Log.ConsoleAppender(formatter)); > +// Set logger to also append to standard out > +logger.addAppender(new Log.DumpAppender(formatter)); If we declare a formatter and appenders at the "addons" level as I suggest above, we don't need them here or in any of the other "addons.*" modules. ::: toolkit/mozapps/extensions/AddonUpdateChecker.jsm @@ +49,2 @@ > > +// Create a new logger for use by the Addons Update Checker White space again ::: toolkit/mozapps/extensions/DeferredSave.jsm @@ +45,5 @@ > // Set up loggers for this instance of DeferredSave > let leafName = OS.Path.basename(aPath); > + > + Cu.import("resource://gre/modules/Log.jsm"); > + const LOGGER_ID = "DeferredSave/" + leafName; This isn't a file-wide constant, it depends on the aPath parameter to the DeferredSave constructor, so it would be better written as let logger_id = "DeferredSave." + leafName; (The old DeferredSave/<fileName> logger string was a bit of a hack so that we could see which instance was logging. In a Log.jsm world, we probably want to use a '.' to separate the string - hopefully that will interact well with whatever we come up with for bug 956817 so that people can easily control DeferredSave logging with preferences) ::: toolkit/mozapps/extensions/PluginProvider.jsm @@ +22,2 @@ > > +// Create a new logger for use by the Addons Plugin Provider Trailing white space ::: toolkit/mozapps/extensions/XPIProvider.jsm @@ +2962,5 @@ > // If either property has changed update the database. > if (wasAppDisabled != aOldAddon.appDisabled || > wasUserDisabled != aOldAddon.userDisabled || > wasSoftDisabled != aOldAddon.softDisabled) { > + logger.debug("Add-on " + aOldAddon.id + " changed appDisabled state to " + Fix indentation to line up with the rest of this block @@ +4617,5 @@ > this.window = aLoadGroup.notificationCallbacks > .getInterface(Ci.nsIDOMWindow); > else > this.window = null; > + Remove white space on this blank line ::: toolkit/mozapps/extensions/XPIProviderUtils.js @@ +29,2 @@ > > +// Create a new logger for use by the Addons XPI Provider Utils Trailing white space ::: toolkit/mozapps/extensions/amWebInstallListener.js @@ +35,2 @@ > > +// Create a new logger for use by the Addons Web Listener Trailing white space

Cheers Irving, this is really helpful -- just wanted to let you know I'm working on attempt three at the minute based on your review comments so it's in progress! Thanks.

Hi Irving, Here's my next attempt at the patch. Removes file: AddonLogging.jsm Edits files: moz.build in toolkit/mozapps/extensions AddonManager.jsm AddonRepository.jsm AddonRepository_SQLiteMigrator.jsm AddonUpdateChecker.jsm DeferredSave.jsm PluginProvider.jsm XPIProvider.jsm XPIProviderUtils.js amWebInstallListener.js Sat 8/2/14 -- Changes made to the patch in this version: 1. Have moved to using parent logger in AddonManager.jsm and child add-on.* loggers 2. DeferredSave.jsm logger name changes. 3. about:config extensions.logging.enabled preferences aspect of removed file AddonLogging.jsm brought over into the new code in AddonManager.jsm and DeferredSave.jsm 4. Whitespace and indentation tidying up on all files involved in the patch. Here are my test results: ./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell Passed: 300 Failed: 0 Todo: 0 Retried: 4 ./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js Passed: 166 Failed: 0 Todo: 0 Let me know what you think. NB when I've been checking my work, the DeferredSave module seems to be active less than previously so I'd appreciate it if you'd check my work in that module especially. Thanks! Emma

Comment on attachment 8373007 [details] [diff] [review] bug-661982-fix.patch Review of attachment 8373007 [details] [diff] [review]: ----------------------------------------------------------------- The code changes are good, but it looks like many of the files went through a reformatter - there are many changes to indentation and line breaks in comments. Can you produce a version of the patch that doesn't have all the white space changes (aside from the trailing white space removals I asked for)? I know this is a pain; we're trying to move toward a standard format that we can automatically enforce, so that we don't have to argue about white space in code reviews, but until then we try to only fix white space on lines we're changing for other reasons. Please request review of the final patch from :Mossop or :Unfocused. (Discussion about code format: https://groups.google.com/d/topic/mozilla.dev.platform/t6ZPxOh-yIA/discussion)

Hi Irving, Dave and Blair, Here's my latest version of the patch. Removes file: AddonLogging.jsm Edits files: moz.build in toolkit/mozapps/extensions AddonManager.jsm AddonRepository.jsm AddonRepository_SQLiteMigrator.jsm AddonUpdateChecker.jsm DeferredSave.jsm PluginProvider.jsm XPIProvider.jsm XPIProviderUtils.js amWebInstallListener.js Sat 15/2/14 -- Changes made to the patch in this version: 1. Rebased whitespace and indentation on all files involved in the patch. This fixes the issues caused by the reformatter in the previous version of the patch. No worries, when sorting this reformatter issue out I learned how to use Mercurial with kdiff3 to do a GUI equivalent of hg qdiff and use the kdiff3 MERGE facility to correct my work which is very handy and saved me loads of time!! :-) After setting up extdiff and kdiff3 in Mercurial .hgrc file, the command I used was: hg extdiff --rev -2 -p kdiff3 Here are my test results: ./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell Passed: 300 Failed: 0 Todo: 0 Retried: 2 ./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js Passed: 166 Failed: 0 Todo: 0 Suggestions for improvement very welcome. Thanks! Emma

Comment on attachment 8376717 [details] [diff] [review] bug-661982-fix.patch Review of attachment 8376717 [details] [diff] [review]: ----------------------------------------------------------------- Unfortunately a patch I landed earlier this week for bug 972852 changed and added a few log messages in XPIProvider.jsm and XPIProviderUtils.js; I'll uploaded an updated version of your patch that fixes those. One more round and this should be ready to land ;-> ::: toolkit/mozapps/extensions/AddonManager.jsm @@ +110,5 @@ > +// If "extensions.logging.enabled" is set to 'true', messages > +// at DEBUG and higher should go to JS console and standard error. > +const PREF_LOGGING_ENABLED = "extensions.logging.enabled"; > +const NS_PREFBRANCH_PREFCHANGE_TOPIC_ID = "nsPref:changed"; > +var gDebugLogEnabled = false; gDebugLogEnabled doesn't need to be a global, since we only use it inside PrefObserver. @@ +134,5 @@ > + try { > + gDebugLogEnabled = Services.prefs.getBoolPref(PREF_LOGGING_ENABLED); > + } > + catch (e) { > + gDebugLogEnabled = false; I know you copied this code directly from AddonLogging.jsm, but if we're switching gDebugLogEnabled away from being a global I'd prefer to set the default value outside the try/catch, i.e. let debugEnabled = false; try { debugEnabled = Services.prefs.... } catch (e) { } ::: toolkit/mozapps/extensions/DeferredSave.jsm @@ +45,5 @@ > // Set up loggers for this instance of DeferredSave > let leafName = OS.Path.basename(aPath); > + > + Cu.import("resource://gre/modules/Log.jsm"); > + let logger_id = "DeferredSave." + leafName; I apologise for missing this on my previous review - this module should declare a parent logger for "DeferredSave" with a preference observer to handle runtime changes to the extensions.logging.enabled preference, as you did for AddonManager. Then each individual DeferredSave object just needs to get a logger for its filename-specific logger_id but doesn't need any additional setup.

Hi Irving, Mossop and Unfocussed, Here's my latest version of the patch which incorporates the updates Irving gave me for bug 972852. Thanks Irving for helping me with that. :-) Removes file: AddonLogging.jsm Edits files: moz.build in toolkit/mozapps/extensions AddonManager.jsm AddonRepository.jsm AddonRepository_SQLiteMigrator.jsm AddonUpdateChecker.jsm DeferredSave.jsm PluginProvider.jsm XPIProvider.jsm XPIProviderUtils.js amWebInstallListener.js Sat 22/2/14 -- Changes made to the patch in this version: 1. Global variable for storing whether debug is enabled, changed into a local variable and changed where it's set. 2. DeferredSave module now has a parent DeferredSave logger and global preference listener acting on the parent logger's logging level. 3. Individual object instances of DeferredSave now each have their own child logger which inherits appenders and logging levels from the parent DeferredSave logger. Here are my test results: ./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell Passed: 300 Failed: 0 Todo: 0 Retried: 2 ./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js Passed: 166 Failed: 0 Todo: 0 I verified the addon.* and DeferredSave.* logging behaviour in the browser and Web Console with about:config extensions.logging.enabled preference set to enabled or disabled. Suggestions for further work needed, further enhancements etc. very welcome. Thanks! Emma

Comment on attachment 8380191 [details] [diff] [review] bug-661982-fix-updated.patch Review of attachment 8380191 [details] [diff] [review]: ----------------------------------------------------------------- Dave (:Mossop) delegated the review to me, so I'll sign off on this. Bah - another major round of bit-rot from bug 952307, which moved a bunch of these files to a subdirectory. If I'd seen that coming I would have told them not to bother moving AddonLogging.jsm... Anyhow, I rebased your patch on top of the changes from bug 952307 and removed the extra imports I mention below, and landed the patch on fx-team: https://hg.mozilla.org/integration/fx-team/rev/4f7128acbae0 I'll attach the as-landed patch for the record. ::: toolkit/mozapps/extensions/DeferredSave.jsm @@ +41,5 @@ > +//If "extensions.logging.enabled" is set to 'true', messages > +//at DEBUG and higher should go to JS console and standard error. > +Cu.import("resource://gre/modules/Services.jsm"); > +Cu.import("resource://gre/modules/XPCOMUtils.jsm"); > +Cu.import("resource://gre/modules/AsyncShutdown.jsm"); Should only need to import Services.jsm here, this module doesn't directly use XPCOMUtils or AsyncShutdown.

Thanks for all your work on this, Emma.

Cheers Irving, thankyou for all your support, advice and very helpful code reviewing :-) Many thanks!

Did this remove logging of error messages to extensions.log in the profile folder?

Hi Dave, Just to confirm, this patch using Log.jsm logs to the Javascript section of the Browser console using Log.ConsoleAppender, and to standard out using Log.DumpAppender only. If you need the equivalent of the AddonLogging.jsm logging to file eg. line 100 in current release: var logfile = FileUtils.getFile(KEY_PROFILEDIR, [FILE_EXTENSIONS_LOG]); then this isn't in this patch and new work would be needed to include it. Cheers, Emma

(In reply to Emma Sajic from comment #23) > Hi Dave, > Just to confirm, this patch using Log.jsm logs to the Javascript section of > the Browser console using Log.ConsoleAppender, and to standard out using > Log.DumpAppender only. > > If you need the equivalent of the AddonLogging.jsm logging to file eg. line > 100 in current release: > var logfile = FileUtils.getFile(KEY_PROFILEDIR, [FILE_EXTENSIONS_LOG]); > > then this isn't in this patch and new work would be needed to include it. > Cheers, > Emma It's Blair's call as module owner but having the log for critical problems has been extremely useful in helping to track down issues users have with add-on installation in the past.

Er, oh - I had been under the impression that that had been included in this patch, to keep parity with the old system. And I agree with Dave, logging to file for this has been *incredibly* useful in the past. There's so many classes of issues we just couldn't have debugged without that persisted log. Filed bug 986887. Ideally we'd uplift that to 30.