944367 - switch thunderbird from own log4moz.js to console.createInstance

Status: RESOLVED FIXED

(Thunderbird :: General, defect, P2)

Description

[Magnus Melin [:mkmelin]]

Toolkit added log4moz.js as Log.jsm in bug 451283. We should switch to using that, and ditch our own copy.

Comment 1

[Sebastian Hengst [:aryx] (needinfo on intermittent or backout)]

As far as I can see, Log.jsm doesn't offer the possibility to log specific loggers based on a preference like Tb's/Gloda's Log4Moz does (getConfiguredLogger). Should we file an enhancement bug for Log.jsm and add that method there? Adding alta88 for providing input as he uses the code for feed logging.

Comment 2

[Magnus Melin [:mkmelin]]

That points to bug 475033 - we just just ditch that, and rework the callers. It's just a very bad idea to modify third-party libraries except for special bug fixes. 

Fortunately it seems like and bug 633498 are the only relevant change we ever made - http://hg.mozilla.org/comm-central/filelog/2f477ef33c92/mailnews/db/gloda/modules/log4moz.js

Comment 3

[alta88]

Log.jsm is inadequate to the purpose of using log4moz in feeds, as it was quite intentionally used in order to enable average users to turn on debugging simply.

I do not understand the 'bad idea' whatsoever and why getConfiguredLogger() shouldn't be ported to toolkit.  There needs to be more debugging capability in Tb, certainly not less.

Comment 4

[Magnus Melin [:mkmelin]]

I have no opinion on those functions as is (haven't really looked in to it), but if it's a third party library patching that heavily makes it non-upgradable so you end up maintaining it yourself. Ugh!

If the functionality is needed, certainly, try to get it into toolkit. Now that Log.jsm is a toolkit lib it has IMO effectively become the upstream library anyways. If it's not acceptable for toolkit, put the extra code in a utility library instead.

We should definitely avoid ending up with a situation someone with experience from other mozilla code can't easily use thunderbird's logging because it somehow differs, if even so slightly.

Comment 5

[alta88]

Sure.  I don't think Log.jsm has anything 3rd party (non moz); the log4moz name seems to have come from some 3rd party convention but that's it.  If Toolkit doesn't want to uplift getConfiguredLogger() then Log.jsm should be extended with it in MailServices or such, to maintain gloda/feeds (and others) log functionality.

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

So, it's worth noting that the fancier stuff in bug 633498 provides some handy stuff like structured logging that provides analyses like so for mozmill failures (he's a recent orange):

https://clicky.visophyte.org/tools/arbpl-mozmill-standalone/?log=https://clicky.visophyte.org/examples/arbpl-mozmill/20131201/mozmill-fail.log

I don't think people are generally aware of the functionality, so I've sent a refresher to tb-planning so anyone who cares can chime in.

(In reply to Magnus Melin from comment #4)
> I have no opinion on those functions as is (haven't really looked in to it),
> but if it's a third party library patching that heavily makes it
> non-upgradable so you end up maintaining it yourself. Ugh!

I agree with your hygiene concerns here, but practically speaking there have been no bugs in Log4moz.jsm and there have been no actual enhancements to Log.jsm other than recent renames for bike-shed reasons when landing it into toolkit.  And the existence of independent loggers logging to stdout/stderr isn't really going to find any interference between the two.

My (current non-contributor, non weight-carrying) suggestion would be to wait until there's something amazing about Log.jsm that log4moz.jsm can't integrate with before undertaking any changes here.  I think the fancier logging calls may have involved some semantic changes as used by mozmill and gloda, so simple changes could break the logging which won't be obvious until something weird happens with gloda and the logs don't work.

Comment 7

[Magnus Melin [:mkmelin]]

Mozmill isn't a concern these days.

From bug 1480327 comment 8:
I think console.createInstance is the new wizardry from a discussion I had the other day (and it is much nicer than the logging modules we have).

Comment 8

[Ping Chen (:rnons)]

Attachment: Bug 944367 - Use ConsoleAPI to replace Log4moz in account creation. r=mkmelin

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/2fa306ccb441
Use ConsoleAPI to replace Log4moz in account creation. r=mkmelin

Comment 10

[Ping Chen (:rnons)]

Attachment: Bug 944367 - Remove Log4Moz from mailWindow, FolderDisplayHelpers and FeedUtils. r=mkmelin

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/94f16bfc2695
Remove Log4Moz from mailWindow, FolderDisplayHelpers and FeedUtils. r=mkmelin

Comment 12

[Magnus Melin [:mkmelin]]

Causing test failures: comm/mail/test/browser/newmailaccount/browser_newmailaccount.js | uncaught exception - TypeError: console.createInstance is not a function at @chrome://messenger/content/accountcreation/util.js:67

... will backout.

Comment 13

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/comm-central/rev/fcaaa25741d9
Backed out changeset 94f16bfc2695 for test failures. r=backout DONTBUILD

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/4ac34f448d10
Remove Log4Moz from mailWindow, FolderDisplayHelpers and FeedUtils. r=mkmelin

Comment 15

[Ping Chen (:rnons)]

Attachment: Bug 944367 - Remove Log4Moz from newmailaccount and mailnews/base. r=mkmelin

Comment 16

[alta88]

Was this at all tested? There is giant console spew for feeds now (trace) and it certainly doesn't work as before, meaning the pref loglevel doesn't give the desired level, ie debug or trace.
Edit: change to pref loglevel is not dynamic with the new method, as it should be, but still requires restart. Trace spew needs to be fixed.

Comment 17

[Ping Chen (:rnons)]

(In reply to alta88 from comment #16)

Was this at all tested? There is giant console spew for feeds now (trace) and it certainly doesn't work as before, meaning the pref loglevel doesn't give the desired level, ie debug or trace.

Sorry, it is fixed by D99755, the reason is Trace and Info have the same level in ConsoleInstance.

Edit: change to pref loglevel is not dynamic with the new method, as it should be, but still requires restart. Trace spew needs to be fixed.

It's dynamic in my testing. Note the level is different from log4moz: https://searchfox.org/mozilla-central/rev/c7cf087b6e1384608ca3989f042f12f7cabd0a5f/dom/console/Console.cpp#2817, and you need to capitalize it.

Comment 18

[Ping Chen (:rnons)]

Attachment: Bug 944367 - Remove Log4Moz from logHelper.js. r=mkmelin

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/d10d28a54f07
Remove Log4Moz from newmailaccount and mailnews/base. r=mkmelin
https://hg.mozilla.org/comm-central/rev/a28a78671024
Remove Log4Moz from logHelper.js. r=mkmelin

Comment 20

[Magnus Melin [:mkmelin]]

We also have a few cases of Log.jsm usage in mail, which I think we can get rid of at the same time:
https://searchfox.org/comm-central/search?q=Log.jsm&path=mail&case=true&regexp=false

Log.jsm is basically the same as Log4Moz, with a few missing features (back in the day Thunderbird was first to import that library into the code base).

Comment 21

[Ping Chen (:rnons)]

Attachment: Bug 944367 - Remove Log4Moz usages from gloda. r=mkmelin

Comment 22

[alta88]

The latest 12/18 nightly shows an even bigger mess:

08:38:56.173 mail.notification: NMNS_Observe: profile-after-change MailNotificationService.jsm:73:15
08:38:56.173 Console.maxLogLevelPref used with a non-existing pref: mail.notification.loglevel

with lots of spew from that and other components now.

This change has fundamentally altered the meaning of Trace and Debug. Either all Trace now has to be All, or Trace is now Debug and Debug is now Log. I suggest you update the codebase to the latter so as to best align with the buttons in the error console.

And a loglevel pref change is not dynamic. Have you done a get messages on a feed with Warn, then changed to Debug and seen any difference? Because it doesn't wfm, on linux.

Comment 23

[Ping Chen (:rnons)]

(In reply to alta88 from comment #22)

The latest 12/18 nightly shows an even bigger mess:

08:38:56.173 mail.notification: NMNS_Observe: profile-after-change MailNotificationService.jsm:73:15
08:38:56.173 Console.maxLogLevelPref used with a non-existing pref: mail.notification.loglevel

with lots of spew from that and other components now.

Yes, D100084 fixed it. The problem is when a loglevel pref is not set, it fallbacks to All. See bug 1683228.

And a loglevel pref change is not dynamic. Have you done a get messages on a feed with Warn, then changed to Debug and seen any difference? Because it doesn't wfm, on linux.

You're right, my second patch in bug 1683228 should fix it. Thanks.

Comment 24

[Ping Chen (:rnons)]

Attachment: Bug 944367 - Remove remaining Log4moz usages and Log4moz.jsm. r=mkmelin

Comment 25

[Ping Chen (:rnons)]

Attachment: Bug 944367 - Replace all Log.jsm usages with console.createInstance. r=mkmelin

Comment 26

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/edfcfeb3910d
Remove Log4Moz usages from gloda. r=mkmelin

Comment 27

[IT Support]

This creates some very noisy output from MailNotificationService.jsm unless one sets mail.notification.loglevel to Error. Is that intentional?

Comment 28

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/1a8dc8afa5a8
Remove remaining Log4moz usages and Log4moz.jsm. r=mkmelin
https://hg.mozilla.org/comm-central/rev/d7d4061c9b34
Replace all Log.jsm usages with console.createInstance. r=mkmelin

Comment 29

[IT Support]

See question in comment #27:
https://searchfox.org/comm-central/search?q=this._log.info&path=MailNotificationService.jsm&case=false&regexp=false

Comment 30

[Ping Chen (:rnons)]

(In reply to IT Support from comment #29)

See question in comment #27:
https://searchfox.org/comm-central/search?q=this._log.info&path=MailNotificationService.jsm&case=false&regexp=false

Hey, are you on the latest nightly? It's been fixed, see https://searchfox.org/comm-central/source/mailnews/mailnews.js#999, no need to set mail.notification.loglevel by yourself.

Comment 31

[IT Support]

Oops, sorry, we observed this in a local build which likely predates this change. We'll do a new build soon.

Comment 32

[Ping Chen (:rnons)]

Attachment: Bug 944367: Lowercase all loglevel pref name and remove unused log prefs. r=mkmelin

Comment 33

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/a9a64b058aaa
Lowercase all loglevel pref name and remove unused log prefs. r=mkmelin

Comment 34

[Magnus Melin [:mkmelin]]

Attachment: bug944367_log4moz_followup.patch

Found 2 remaining obsolete references.

Comment 35

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/deeb60864867
remove stray Log4Moz references. r=rnons