Add-ons Manager logging should log to file using Log.jsm's FileAppender

RESOLVED WONTFIX

Status

()

defect
RESOLVED WONTFIX
6 years ago
2 years ago

People

(Reporter: Unfocused, Unassigned)

Tracking

(Depends on 1 bug, {regression})

unspecified
Points:
---
Dependency tree / graph
Bug Flags:
firefox-backlog +
in-testsuite +

Firefox Tracking Flags

(firefox30- affected, firefox31 affected)

Details

(Whiteboard: [lang=js])

Attachments

(1 attachment, 4 obsolete attachments)

This should mimic the old system - warnings/errors always go to extensions.log file, unless the extensions.logging prefs is set to true, in which case everything gets logged to file.
I meant to note, bug 661982 removed logging to file in switching over to use Log.jsm, and is on 30. So ideally we'd uplift this to 30.
This is a regression from Firefox 30
Keywords: regression
Emma, do you want to look at this (or does anyone else)?

I expect this just needs the addition of a FileAppender to the logging configuration at the top of AddonManager.jsm.

Not that you'd want to walk too many users through this, but one nice thing about Log.jsm is that you can also make these sort of logging changes on the fly in the Browser Console.
Whiteboard: [mentor=irving][lang=js]
Hi Irving,
yes I have some time today to work on this.

I'm assuming that the "special" Profile Directory is to be used (as mentioned in https://developer.mozilla.org/en-US/Add-ons/Code_snippets/File_I_O ) and that the log file is to be called extension.log to keep it consistent with the way it worked before in AddonLogging.jsm.

From my work on bug 661982 it looks to me like there should be a FileAppender added to DeferredSave.jsm as well as in AddonManager.jsm -- I'll make a patch for both those modules and get back to you.

Thanks,
Emma
Sorry I meant extensions.log not extension.log! Cheers.
Posted patch bug-986877-fix.patch (obsolete) — Splinter Review
Hi Irving,
Here's my first attempt at the bug 986887 patch.

Edits files:
AddonManager.jsm in toolkit/mozapps/extensions
DeferredSave.jsm in toolkit/mozapps/extensions

Sat 29/3/14 -- What's in the patch in this version:
1. AddonManager.jsm parent logger now has an additional appender -- a FileAppender which logs to extensions.log in the Profile directory.
2. DeferredSave.jsm parent logger now has an additional appender -- a FileAppender which logs to extensions.log in the Profile directory.

The Profile directory is being looked up dynamically using the ProfD key.

The existing work I did on extensions logging preferences in AddonManager.jsm and DeferredSave.jsm still stands, so if you change the value of that setting in about:config then that will be reflected in the logging level of events that get logged to extensions.log file, as well as events that get logged to the Browser Console or Standard Out. I haven't needed to modify any code to make that work. 

Here are my test results:
./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js
Passed: 166 Failed: 0 Todo: 0

./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell
Passed: 0 Failed: 302 Todo: 0 Retried: 278

The xpcshell extensions tests seem to be refusing to run on my Mac at the minute. They are all giving this WARNING:
 WARNING: Couldn't get the user appdata directory. Crash events may not be produced.

Manual Unit testing:
I verified the addon.* logging behaviour in the Profile Directory extensions.log file with about:config extensions.logging.enabled preference set to enabled or disabled.

When I tested the patch on my Mac it created the extensions.log file in the folder ~/Library/Application Support/Firefox/Profiles/acbc2iws.default/

Suggestions for further work needed, further enhancements etc. very welcome.
Thanks!
Emma
Attachment #8398959 - Flags: review?(irving)
Comment on attachment 8398959 [details] [diff] [review]
bug-986877-fix.patch

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

Also, I noticed that when I rebased the patch in bug bug 661982 because another patch had moved several of the files, I didn't correctly merge the removal of internal/AddonLogging.jsm - can you please remove that in this patch too?

::: toolkit/mozapps/extensions/AddonManager.jsm
@@ +99,5 @@
> +// Set parent logger (and its children) to
> +// log to the extensions log file in the profile directory
> +Cu.import("resource://gre/modules/FileUtils.jsm");
> +const KEY_PROFILEDIR = "ProfD";
> +const FILE_EXTENSIONS_LOG = "extensions.log";

This is the same code as was in AddonLogging.jsm, but Blair and I think we should change this to use the "local profile" directory (the key is "ProfLD"). The difference is only significant on Windows systems with user profiles mounted from a network file server; ProfLD is on the local drive so our log writes will be faster.

Unfortunately, the current implementation of Log.jsm doesn't automatically close the file, so you'll also need to add a call to appender.reset() in AddonManager.shutdown() - it returns a Promise, so you'll need to add it to the promise.then chain returned by shutdown().

::: toolkit/mozapps/extensions/DeferredSave.jsm
@@ +37,5 @@
> +Cu.import("resource://gre/modules/FileUtils.jsm");
> +const KEY_PROFILEDIR = "ProfD";
> +const FILE_EXTENSIONS_LOG = "extensions.log";
> +let logfile = FileUtils.getFile(KEY_PROFILEDIR, [FILE_EXTENSIONS_LOG]);
> +parentLogger.addAppender(new Log.FileAppender(logfile.path, formatter));

I don't think we need DeferredSave.jsm to log into extensions.log; the old code didn't really do that on purpose, it just happened because we were using AddonLogging.jsm.

Also, FileAppender will open the file once for each appender, and doesn't take care to manage multiple access to the same file, so I'm nervous that it's not safe to have more than one appender for the same file.
Attachment #8398959 - Flags: review?(irving) → feedback+
Posted patch bug-986877-fix.patch (obsolete) — Splinter Review
Hi Irving,
Thanks very much for this -- I've reworked the bug 986887 patch in line with your review comments.

Edits files:
AddonManager.jsm in toolkit/mozapps/extensions
moz.build in toolkit/mozapps/extensions/internal

Sun 6/4/14 -- What's in the patch in this version:
1. AddonManager.jsm: parent logger now has a FileAppender which logs to extensions.log in the LOCAL Profile directory (Key ProfLD). The FileAppender is referred to by a variable so that reset() can be called on it later to close the file.
2. AddonManager.jsm: In the AddonManager shutdown method I've added A "Promise then" call to run reset() on the FileAppender and another chained "Promise then" to evaluate whether the Promise that reset() returns has been Fulfilled or Rejected -- if Rejected I log an error.
3. moz.build for the internal folder -- I've removed the reference to AddonLogging.jsm
I couldn't find any other references to AddonLogging.jsm in the current Mozilla Central repository on MXR so I've assumed that was the only thing left outstanding on the merge -- if I'm wrong just let me know.

Here are my test results:
./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js
Passed: 166 Failed: 0 Todo: 0

./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell

The xpcshell extensions tests are still refusing to run on my Mac. They are all giving this WARNING:
 WARNING: Couldn't get the user appdata directory. Crash events may not be produced.

Manual Unit testing:
I verified the addon.* and DeferredSave logging behaviour in the Local Profile Directory extensions.log file with about:config extensions.logging.enabled preference set to enabled or disabled.

NB the extensions.log file only gets created if there are addon.* events logged. DeferredSave events are not being logged to file in this patch (but they are still being logged to Browser Console and Standard Out).

When I tested the patch on my Mac it created the extensions.log file in the folder ~/Library/Caches/Firefox/Profiles/acbc2iws.default/

This means that on my Mac the Local Profile Directory is coming up as being NOT the same directory as the Profile Directory (~/Library/Application Support/Firefox/Profiles/acbc2iws.default/).

This means that if I use a Firefox add-in to Open the Profile directory the extensions.log file will not be seen in there.

Further changes needed just let me know.
Thanks!
Emma
Attachment #8398959 - Attachment is obsolete: true
Attachment #8402288 - Flags: review?(irving)
Comment on attachment 8402288 [details] [diff] [review]
bug-986877-fix.patch

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

::: toolkit/mozapps/extensions/AddonManager.jsm
@@ +98,5 @@
>  parentLogger.addAppender(new Log.DumpAppender(formatter));
> +// Set parent logger (and its children) to
> +// log to the extensions log file in the profile directory
> +Cu.import("resource://gre/modules/FileUtils.jsm");
> +const KEY_PROFILEDIR = "ProfLD";

Just chatted with :mossop on IRC, and because we have a fair bit of documentation and established support procedures around the extensions.log file he asked me to put it back in the main profile directory "ProfD".

@@ +101,5 @@
> +Cu.import("resource://gre/modules/FileUtils.jsm");
> +const KEY_PROFILEDIR = "ProfLD";
> +const FILE_EXTENSIONS_LOG = "extensions.log";
> +let logfile = FileUtils.getFile(KEY_PROFILEDIR, [FILE_EXTENSIONS_LOG]);
> +let parentFileAppender = new Log.FileAppender(logfile.path, formatter); 

Please remove trailing white space from this line (./mach mercurial-setup will set hg diff options that highlight extra white space).

This line was failing (and the attempt to report the error was also failing) when I tried to run the tests on Mac OS X, which was part of why all the tests were failing for you. You should put a try/catch around the getFile() and new Log.FileAppender() calls, and handle the possibility of no parentFileAppender in shutdown().

Turns out the underlying cause of the failure in the xpcshell suite was rather obscure - the test harness uses a mock profile directory, created by calling do_get_profile() in head_addons.js. We are currently loading AddonManager.jsm, and thus trying to open [ProfLD]/extensions.log, before do_get_profile() is called, so the mock profile isn't set up yet and the call fails.

The fix for this is to move the line 'const gProfD = do_get_profile()' in head_addons.js to before all the Components.utils.import() lines.

::: toolkit/mozapps/extensions/internal/moz.build
@@ -6,5 @@
>  
>  JS_MODULES_PATH = 'modules/addons'
>  
>  EXTRA_JS_MODULES += [
> -    'AddonLogging.jsm',

You also need to "hg remove" the actual internal/AddonLogging.jsm file.
Attachment #8402288 - Flags: review?(irving) → feedback+
Assignee: nobody → esajic
Status: NEW → ASSIGNED
Posted patch bug-986877-fix.patch (obsolete) — Splinter Review
Hi Irving,
Cheers for your help on this -- here's a new attempt at the bug 986887 patch.

Edits files:
AddonManager.jsm in toolkit/mozapps/extensions
moz.build in toolkit/mozapps/extensions/internal
head_addons.js in toolkit/mozapps/extensions/test/xpcshell

Removes files
AddonLogging.jsm in toolkit/mozapps/extensions/internal

Tue 8/4/14 -- What's in the patch in this version:
1. AddonManager.jsm: parent logger now has a FileAppender which logs to extensions.log in the "standard" Profile directory (Key ProfD). The FileAppender is referred to by a variable so that reset() can be called on it later to close the file. There's a try-catch round the attempt to get the file path and the attempt to create the FileAppender. I've added some "belt and braces" exception logging to the catch as we don't have a logger yet at that point (we're still configuring the parent logger) -- let me know if this doesn't suit.
2. AddonManager.jsm: In the AddonManager shutdown method I've added A "Promise then" call to run reset() on the FileAppender and another chained "Promise then" to evaluate whether the Promise that reset() returns has been Fulfilled or Rejected -- if Rejected I log an error. The code now checks whether the FileAppender is null before attempting to reset().
3. moz.build for the internal folder -- I've removed the reference to AddonLogging.jsm
and done hg remove on internal/AddonLogging.jsm file itself
4. Whitespace corrected in the line where it was faulty in previous patch in AddonManager.jsm.
5. head_addons.js -- moved the call to do_get_profile() to before importing AddonManager.jsm

Thanks for telling me about the mach mercurial setup script, I wasn't aware of that and it's very useful!

Here are my test results:
./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js
Passed: 166 Failed: 0 Todo: 0

./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell
Passed: 304 Failed: 0 Todo: 0 Retried: 4

Manual Unit testing:
I verified the addon.* and DeferredSave logging behaviour in the Local Profile Directory extensions.log file with about:config extensions.logging.enabled preference set to enabled or disabled.

As before, the extensions.log file only gets created if there are addon.* events logged. DeferredSave events are not being logged to file in this patch (but they are still being logged to Browser Console and Standard Out).

When I tested the patch on my Mac it created the extensions.log file in the folder ~/Library/Application Support/Firefox/Profiles/acbc2iws.default/

So when I use a Firefox add-in to Open the Profile directory the extensions.log file does appear in there.

Any more work needed just let me know.
Thanks!
Emma
Attachment #8402288 - Attachment is obsolete: true
Attachment #8403598 - Flags: review?(irving)
Comment on attachment 8403598 [details] [diff] [review]
bug-986877-fix.patch

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

One more fix and it's ready to land.

::: toolkit/mozapps/extensions/AddonManager.jsm
@@ +889,5 @@
>            delete this.startupChanges[type];
>          gStarted = false;
>          gStartupComplete = false;
> +      })
> +      .then(() => { if (parentFileAppender !== null) { parentFileAppender.reset(); } })

FileAppender.reset() may return a promise, and you want the subsequent .then() to wait for that promise to resolve, so your in-line function in the .then() handler needs to return the promise. That was happening by default in your previous version of the patch, because ES6 arrow functions containing a single expression default to returning the result of that expression, but because of the if..then statement in the new patch you need to either make the return explicit or use the ? : operator, like

.then(() => parentFileAppender ? parentFileAppender.reset() : null)
Attachment #8403598 - Flags: review?(irving) → feedback+
Posted patch bug-986877-fix.patch (obsolete) — Splinter Review
Hi Irving,
Thanks for the info about the Arrow Function!
I have edited it and here's my latest attempt at the bug 986887 patch.

Edits files:
AddonManager.jsm in toolkit/mozapps/extensions
moz.build in toolkit/mozapps/extensions/internal
head_addons.js in toolkit/mozapps/extensions/test/xpcshell

Removes files
AddonLogging.jsm in toolkit/mozapps/extensions/internal

Weds 9/4/14 -- What's in the patch in this version:
1. AddonManager.jsm: parent logger now has a FileAppender which logs to extensions.log in the "standard" Profile directory (Key ProfD). There's a try-catch round the attempt to get the file path and the attempt to create the FileAppender, which outputs any exceptions caught to debug console and standard out.
2. AddonManager.jsm: In the AddonManager shutdown method I've added A "Promise then" call to run reset() on the FileAppender and another chained "Promise then" to evaluate whether the Promise that reset() returns has been Fulfilled or Rejected -- if Rejected I log an error. The code now checks whether the FileAppender is null before attempting to reset() and it returns the Promise resulting from reset() where applicable.
3. moz.build for the internal folder -- I've removed the reference to AddonLogging.jsm
and done hg remove on internal/AddonLogging.jsm file itself
4. head_addons.js -- moved the call to do_get_profile() to before importing AddonManager.jsm

Here are my test results:
./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js
Passed: 166 Failed: 0 Todo: 0

./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell
Passed: 304 Failed: 0 Todo: 0 Retried: 4

Manual Unit testing:
I verified the addon.* and DeferredSave logging behaviour in the Local Profile Directory extensions.log file with about:config extensions.logging.enabled preference set to enabled or disabled.

As before, the extensions.log file only gets created if there are addon.* events logged. DeferredSave events are not being logged to file in this patch (but they are still being logged to Browser Console and Standard Out).

The extensions.log file gets created in the "standard" Profile directory as before.

Hope this is ok, any more changes needed just let me know.
Thanks!
Emma
Attachment #8403598 - Attachment is obsolete: true
Attachment #8404271 - Flags: review?(irving)
Comment on attachment 8404271 [details] [diff] [review]
bug-986877-fix.patch

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

Looks good, ready to land.
Attachment #8404271 - Flags: review?(irving) → review+
Flags: firefox-backlog?
Flags: firefox-backlog? → firefox-backlog+
https://hg.mozilla.org/integration/fx-team/rev/16a75e1c76d0
Flags: in-testsuite+
Keywords: checkin-needed
Whiteboard: [mentor=irving][lang=js] → [mentor=irving][lang=js][fixed-in-fx-team]
Backed out for xpcshell failures on all platforms. Please make sure this goes through Try before requesting checkin again.
https://hg.mozilla.org/integration/fx-team/rev/7258a13fb245

https://tbpl.mozilla.org/php/getParsedLog.php?id=37723343&tree=Fx-Team
Whiteboard: [mentor=irving][lang=js][fixed-in-fx-team] → [mentor=irving][lang=js]
Hi Irving,
Have had a quick look and am wondering if this is anything to do with the unload and reload of AddonManager.jsm in

/toolkit/mozapps/extensions/test/xpcshell/test_childprocess.js

I also noticed there's no function to get the profile directory for the new AddonManager logging to file to use, in place in test_childprocess.js ( in head_addons.js we had the do_get_profile() function to do this ).

Cheers,
Emma
Ah, the devtools tests that are failing in the log RyanVM linked to are annoying - they watch the console service and error out if anything sends a message to the console that they don't expect.

Perhaps the right thing to do is move the setup of the FileAppender to the beginning of AddonManager.startup() rather than doing it when the module loads, and do a corresponding removeAppender() after the reset() in AddonManager.shutdown().
Flags: needinfo?(esajic)
Hi Irving,
Thanks, that makes sense -- I've reworked the patch now based on your suggestions.

Edits files:
AddonManager.jsm in toolkit/mozapps/extensions
moz.build in toolkit/mozapps/extensions/internal
head_addons.js in toolkit/mozapps/extensions/test/xpcshell

Removes files
AddonLogging.jsm in toolkit/mozapps/extensions/internal

Sun 27/4/14 -- Here's what's new (different from previous patch)
All the differences from the previous patch are in AddonManager.jsm:
1. When I downloaded the latest source code from Mozilla Central today I noticed that there was a KEY_PROFILEDIR constant already defined at the top of the module and my last patch when reapplied was creating a duplicate so I've fixed that.
2. File extensions log constant has been moved to the top of the module near KEY_PROFILEDIR, it's tidier.
3. I've moved the code to set up the FileAppender into the AddonManager startup method.
4. In the AddonManager shutdown method I've added to the "Promise then" call which runs reset() on the FileAppender,  so that after attempting reset it removes the FileAppender.

Here are my test results:
./mach mochitest-browser browser/base/content/test/general/browser_bug553455.js
Passed: 166 Failed: 0 Todo: 0

./mach xpcshell-test toolkit/mozapps/extensions/test/xpcshell
Passed: 308 Failed: 0 Todo: 0 Retried: 6

./mach xpcshell-test toolkit/modules/tests/xpcshell
Passed: 20 Failed: 0 Todo: 0 Retried: 0

Manual Unit testing:
I verified the addon.* and DeferredSave logging behaviour in the Local Profile Directory extensions.log file with about:config extensions.logging.enabled preference set to enabled or disabled.

extensions.log file location and behaviour should be as before.

Hope this will help sort out the build server issues -- any more changes needed just let me know.
Cheers!
Emma
Attachment #8404271 - Attachment is obsolete: true
Flags: needinfo?(esajic)
Attachment #8413360 - Flags: review?(irving)
Comment on attachment 8413360 [details] [diff] [review]
bug-986877-fix.patch

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

This looks good, aside from the issue I identified in bug 997368 - when I advised you to use FileAppender.reset(), I hadn't noticed that reset both closes *and removes* the log file, which is not what we want.

Would you be willing to take on bug 997368, to add a close() method to all the Appenders (it may need to be async for some appenders) and then use that in this patch?

I want to wait until we can cleanly close the log files before we land this patch.
Attachment #8413360 - Flags: review?(irving)
Hi Irving,
About FileAppender.reset(), when I was running the manual checks on my patch from the 27th April code the extensions log file never got deleted from the local profile directory although I ran the code and opened and closed NightlyDebug browser several times -- maybe bug 997368 is operating system specific -- I'm on a Mac running OS X 10.7.5.

Apologies but I haven't got the spare time right now to be able to take on 997368 -- suggest you reassign both 986887 and 997368 to a developer who can take what I've done so far, further forward, and work on these two bugs as a set as it's looking like they're interlinked now.

Cheers,
Emma
Sorry when I said "local profile directory" in comment 20 I meant the "standard" Profile directory (Key ProfD)!
Cheers,
Emma
While it's a regression, this isn't something that will majorly affect users and we can accept a low risk fix for uplift when ready but wouldn't hold a release for this.
Mentor: irving
Whiteboard: [mentor=irving][lang=js] → [lang=js]
Assignee: esajic → nobody
Mentor: irving
Status: ASSIGNED → NEW
We no longer log anything to file.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.