1049774 - GMPInstallManager logs when logging disabled

Status: RESOLVED FIXED

(Toolkit :: General, defect)

Description

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

With a release build and clean profile (where media.gmp-manager.log === false), there are still quite a few logs sent to the console:

1407350503382	GMPInstallManager.simpleCheckAndInstall	INFO	Last check was: 1407350503 seconds ago, minimum seconds: 86400
1407350503383	GMPInstallManager._getURL	INFO	Using url: https://aus4.mozilla.org/update/3/GMP/%VERSION%/%BUILD_ID%/%BUILD_TARGET%/%LOCALE%/%CHANNEL%/%OS_VERSION%/%DISTRIBUTION%/%DISTRIBUTION_VERSION%/update.xml
1407350503383	GMPInstallManager._getURL	INFO	Using url (with replacement): https://aus4.mozilla.org/update/3/GMP/34.0a1/20140806124257/Darwin_x86_64-gcc3/en-US/default/Darwin%2013.3.0/default/default/update.xml
1407350503385	GMPInstallManager.checkForAddons	INFO	sending request to: https://aus4.mozilla.org/update/3/GMP/34.0a1/20140806124257/Darwin_x86_64-gcc3/en-US/default/Darwin%2013.3.0/default/default/update.xml
1407350503744	GMPInstallManager.onLoadXML	INFO	request completed downloading document
1407350503745	GMPInstallManager.onLoadXML	INFO	allowNonBuiltIn: false
1407350503753	GMPInstallManager.simpleCheckAndInstall	INFO	Found 1 addons advertised.
1407350503753	GMPInstallManager.simpleCheckAndInstall	INFO	Found addon: gmp-gmpopenh264 (isValid: true, isInstalled: true, isOpenH264: true, hashFunction: SHA512, hashValue: 0eac05de3b9dd939ece57450bcddf6fee04415a99744a0ce46ddb19c1205cbaf4d8c5a7b5efc2158c9fb257a7948024ed1604890b56382513922107e22273165, size: 282746)
1407350503753	GMPInstallManager.simpleCheckAndInstall	INFO	No new addons to install, returning

Can we disable these so they are not emitted when media.gmp-manager.log === false?

Comment 2

[Daniel Holbert [:dholbert]]

I poked at this a bit, because I really want this noise to go away.

The logging pref does correctly set "gLogEnabled" to false, but gLogEnabled doesn't actually do what you'd expect it to do.

Its only usage is here:
> 58 function getScopedLogger(prefix) {
> 59   var parentScope = gLogEnabled ? PARENT_LOGGER_ID + "." : "";
> 60   return Log.repository.getLogger(parentScope + prefix);
> 61 }
http://mxr.mozilla.org/mozilla-central/source/toolkit/modules/GMPInstallManager.jsm#58

All gLogEnabled does there is control whether PARENT_LOGGER_ID + "." gets prepended onto all of the logged messages or not.  That's it.  It doesn't actually enable/disable logging at all.

For this to work correctly, getScopedLogger needs to either:
 (1) return null when the gLogEnabled is false (and the callers need to be able to handle that)
...or...
 (2) set the "level" on the returned Log to something highish.


Also, FWIW, we have this other log that appears to be completely unused:
> 35 // Setup the parent logger with dump logging. It'll only be used if logging is
> 36 // enabled though.
> 37 let parentLogger = Log.repository.getLogger(PARENT_LOGGER_ID);
> 38 parentLogger.level = Log.Level.Debug;
> 39 let appender = new Log.DumpAppender();
> 40 parentLogger.addAppender(appender);

Comment 3

[Daniel Holbert [:dholbert]]

Also, when the pref is set and |PARENT_LOGGER_ID + "."| does get prepended, it's redundant, because PARENT_LOGGER_ID is "GMPInstallManager", and all of the getScopedLogger() calls already include "GMPInstallManager." hardcoded into their argument. e.g.:
> 297     let log = getScopedLogger("GMPInstallManager._getURL");

Comment 4

[Brian R. Bondy [:bbondy]]

Thanks for investigating it dholbert, I'll start on this soon.

Comment 5

[Brian R. Bondy [:bbondy]]

Attachment: patch rev1.

Comment 6

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8488435 [details] [diff] [review]
patch rev1.

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

::: toolkit/modules/GMPInstallManager.jsm
@@ +57,2 @@
>  function getScopedLogger(prefix) {
>    var parentScope = gLogEnabled ? PARENT_LOGGER_ID + "." : "";

What do we actually need this for? Why don't we always prefix with "GMPInstallManager."?

@@ +57,3 @@
>  function getScopedLogger(prefix) {
>    var parentScope = gLogEnabled ? PARENT_LOGGER_ID + "." : "";
> +  var logger = Log.repository.getLogger(parentScope + prefix);

Lets make both lines |let| instead of |var|.

Comment 7

[Brian R. Bondy [:bbondy]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #6)
> Comment on attachment 8488435 [details] [diff] [review]
> patch rev1.
> 
> Review of attachment 8488435 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: toolkit/modules/GMPInstallManager.jsm
> @@ +57,2 @@
> >  function getScopedLogger(prefix) {
> >    var parentScope = gLogEnabled ? PARENT_LOGGER_ID + "." : "";
> 
> What do we actually need this for? Why don't we always prefix with
> "GMPInstallManager."?

Having that scopes it to the parent logging so it uses parentLogger. Using parent logging was done so that we don't get multiple logs.

> 
> @@ +57,3 @@
> >  function getScopedLogger(prefix) {
> >    var parentScope = gLogEnabled ? PARENT_LOGGER_ID + "." : "";
> > +  var logger = Log.repository.getLogger(parentScope + prefix);
> 
> Lets make both lines |let| instead of |var|.

Will do, it's the same in this case though.

Comment 8

[Brian R. Bondy [:bbondy]]

> Why don't we always prefix with "GMPInstallManager."

Everything will be prefixed with GMPInstallManager based on the parent logger.

Comment 9

[Brian R. Bondy [:bbondy]]

Attachment: patch rev2.

s/var/let

Comment 10

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8488622 [details] [diff] [review]
patch rev2.

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

As discussed on IRC, the gLogEnabled usage here is confusing, but unrelated to this bug.
We should have a follow-up to fix that or at least comment on what it is supposed to do.

Comment 11

[Brian R. Bondy [:bbondy]]

I'll try to change it to being controlled completely on the parent logger. I think that would be easier to read if that's possible.

Comment 12

[Brian R. Bondy [:bbondy]]

Comment on attachment 8488622 [details] [diff] [review]
patch rev2.

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

This works but I'll try to do another pass to control everything from the parent logger. I think it'd be easier to read that way.

Comment 13

[Brian R. Bondy [:bbondy]]

Attachment: bug1049774.diff

Breaking the link to the parent logger turned out to not be needed at all.
That's what I was using originally to determine if a dumplogger would be added, but for whatever reason it was still being logged. So this changes the strategy to simply set the log level from the pref at the parent logger level.

Comment 14

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8488642 [details] [diff] [review]
bug1049774.diff

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

Ah, that looks much clearer, thanks.

Comment 15

[Brian R. Bondy [:bbondy]]

Attachment: Disable logging in a different way

Carrying forward r+.
Minor fix needed where I was using GMPPrefs earlier than it was defined because of moving gLogEnabled.

Comment 16

[Brian R. Bondy [:bbondy]]

On a side note about this bug, for me the old way i was disabling logging still worked. So I'm not sure what the env differences are.  Because in the old way there was no parent logger association and hence no dump logger added.   

I verified both with the old and the new way, but both ways for me leads to the pref working.
I think the new way will probably have a better chance for working for those who could reproduce though.

Comment 17

[Daniel Holbert [:dholbert]]

I verified (over the weekend) that the patch disables logging for me. (I typed up a comment to say that, but I think I forgot to submit it.)

Hooray! Let's get this landed. :)

Comment 18

[Daniel Holbert [:dholbert]]

[platform->All/All, since I'm hitting this on 64-bit linux, not 32-bit Mac]

Comment 19

[Brian R. Bondy [:bbondy]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3d0678d55653

Comment 20

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/3d0678d55653

Comment 22

[Tom Roche]

Just wondering: what can a user of firefox version < 35 do to mitigate the performance hit until version=35 lands? I'm running packaged firefox:

$ lsb_release -ds
LMDE Cinnamon Edition
$ cat /etc/debian_version
jessie/sid
$ uname -rv
3.11-2-amd64 #1 SMP Debian 3.11.8-1 (2013-11-13)
$ gcc --version | head -n 1
gcc (Debian 4.8.2-1) 4.8.2
$ firefox --version
(process:9861): GLib-CRITICAL **: g_slice_set_config: assertion `sys_page_size == 0' failed
Mozilla Firefox 33.0

and firefox seems quite sluggish lately. I start it from a terminal, and, in that terminal, get intermittent occurrences of, e.g.,

1416531177837   GMPInstallManager.simpleCheckAndInstall INFO    Last check was: 36471 seconds ago, minimum seconds: 86400
1416531177837   GMPInstallManager.simpleCheckAndInstall INFO    Will not check for updates.

"intermittent" == often firefox will log lines like that for many minutes at a time @ 20-30 sec intervals, though infrequently they double (e.g.,

1416530342882   GMPInstallManager.simpleCheckAndInstall INFO    Last check was: 35636 seconds ago, minimum seconds: 86400
1416530342883   GMPInstallManager.simpleCheckAndInstall INFO    Will not check for updates.
1416530342903   GMPInstallManager.simpleCheckAndInstall INFO    Last check was: 35636 seconds ago, minimum seconds: 86400
1416530342905   GMPInstallManager.simpleCheckAndInstall INFO    Will not check for updates.

), but sometimes no logging at all for extended periods.

Comment 23

[Georg Fritzsche [:gfritzsche]]

This should not be a relevant performance issue - the update checks don't happen often anyway.