1122049 - Add logging to Telemetry.

Status: RESOLVED FIXED

(Firefox Health Report Graveyard :: Client: Desktop, defect)

Description

[Alessio Placitelli [:Dexter]]

We need to add logging to telemetry (Log.jsm), plus the related config & preferences.

Comment 1

[Alessio Placitelli [:Dexter]]

Attachment: Add simple logging to TelemetryPing.

This patch adds logging to TelemetryPing.

Comment 2

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8551780 [details] [diff] [review]
Add simple logging to TelemetryPing.

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

::: toolkit/components/telemetry/TelemetryPing.jsm
@@ +31,5 @@
>  // This is the HG changeset of the Histogram.json file, used to associate
>  // submitted ping data with its histogram definition (bug 832007)
>  #expand const HISTOGRAMS_FILE_VERSION = "__HISTOGRAMS_FILE_VERSION__";
>  
> +const LOGGER_NAME = "toolkit.Telemetry";

Nit: Lets stay consistent with case here: "Toolkit.Telemetry"

@@ +37,4 @@
>  const PREF_BRANCH = "toolkit.telemetry.";
>  const PREF_SERVER = PREF_BRANCH + "server";
>  const PREF_ENABLED = PREF_BRANCH + "enabled";
> +const PREF_LOG_LEVEL = PREF_BRANCH + "log.level";

Also "log.dump" please?

@@ +157,5 @@
>    /**
> +   * Returns the top level telemetry logger.
> +   * @returns Object
> +   */
> +  getLogger: function() {

I don't think we need to expose this.

@@ +274,5 @@
>  
>  let Impl = {
>    _histograms: {},
>    _initialized: false,
> +  _logger: null,

Just _log?

@@ +300,5 @@
>  
>    /**
> +   * Setup Telemetry logging and observe logging related preferences.
> +   */
> +  configureLogging: function() {

Lets add a dump appender here - see e.g. Experiments.jsm.

@@ +327,5 @@
>     *
>     * @return simple measurements as a dictionary.
>     */
>    getSimpleMeasurements: function getSimpleMeasurements(forSavedSession) {
> +    this._logger.info("Gathering simple measurements.");

Maybe just e.g. |this._log.trace("getSimpleMeasurements");| for that kind of logging?

@@ +565,5 @@
>     *         returned metadata,
>     * @return The metadata as a JS object
>     */
>    getMetadata: function getMetadata(reason) {
> +    this._logger.info("Getting metadata.");

Lets add the reason.

@@ +864,5 @@
>      return payloadObj;
>    },
>  
>    getSessionPayload: function getSessionPayload(reason) {
> +    this._logger.info("Getting session payload.");

+ reason

@@ +876,5 @@
>      return { slug: slug, reason: reason, payload: payloadObj };
>    },
>  
>    getSessionPayloadAndSlug: function getSessionPayloadAndSlug(reason) {
> +    this._logger.info("Getting session payload and slug.");

+ reason

@@ +899,5 @@
>    /**
>     * Send data to the server. Record success/send-time in histograms
>     */
>    send: function send(reason, server) {
> +    this._logger.info("Sending data to the server.");

+ reason & server?

@@ +1035,5 @@
>        // We can't send data; no point in initializing observers etc.
>        // Only do this for official builds so that e.g. developer builds
>        // still enable Telemetry based on prefs.
>        Telemetry.canRecord = false;
> +      this._logger.debug("Can't send data, disable Telemetry recording.");

this._log.config()?
Nit: "disabling"

@@ +1046,5 @@
>      if (!enabled) {
>        // Turn off local telemetry if telemetry is disabled.
>        // This may change once about:telemetry is added.
>        Telemetry.canRecord = false;
> +      this._logger.debug("Telemetry is disabled, turning off Telemetry recording.");

this._log.config()?

@@ +1075,5 @@
>        Preferences.set(PREF_PREVIOUS_BUILDID, thisBuildID);
>      }
>  
>      if (!this.enableTelemetryRecording(testing)) {
> +      this._logger.config("Telemetry recording is disabled, skipping Chrome process setup.");

To make it more easy to identify where this comes from i'd suggest to keep with prefixing (this._log.config("setupChromeProcess - ...")) or use something like getScopedLogger().

@@ +1308,5 @@
>          this.sendContentProcessPing("saved-session");
>        }
>        break;
>      case "cycle-collector-begin":
> +      this._logger.debug(aTopic + " topic notified.");

We can just put one statement for topic logging at the top here.

Comment 3

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch

Thanks for the review! This patch implements the suggested changes.

Comment 4

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v2

Comment 5

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v3

Makes sure logging is initialised during tests.

Comment 6

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8551902 [details] [diff] [review]
bug1122049.patch - v2

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

::: toolkit/components/telemetry/TelemetryPing.jsm
@@ +298,5 @@
>    /**
> +   * Setup Telemetry logging. This function also gets called when loggin related
> +   * preferences change.
> +   */
> +  configureLogging: function() {

I don't think there is a need for this (and _logAppender/_logEnableDump) to be members.

@@ +312,5 @@
> +    this._log.level = Log.Level[Preferences.get(PREF_LOG_LEVEL, "Warn")];
> +
> +    // If enabled in the preferences, add a dump appender.
> +    let logDumping = Preferences.get(PREF_LOG_DUMP, false);
> +    if (logDumping != this._logEnableDump) {

Reading this here, _logEnableDump looks redundant to !!_logAppenderDump.

@@ +903,5 @@
>    /**
>     * Send data to the server. Record success/send-time in histograms
>     */
>    send: function send(reason, server) {
> +    this._log.trace("send - Reason " + reason + " Server " + server);

", Server " or some other separator?

@@ +1014,5 @@
>        return;
>      Services.obs.addObserver(this, "cycle-collector-begin", false);
>      Services.obs.addObserver(this, "idle-daily", false);
> +    Preferences.observe(PREF_LOG_LEVEL, this.configureLogging, this);
> +    Preferences.observe(PREF_LOG_DUMP, this.configureLogging, this);

I think you can just observe |PREF_BRANCH + "log."|?

@@ +1063,5 @@
>    /**
>     * Initializes telemetry within a timer. If there is no PREF_SERVER set, don't turn on telemetry.
>     */
>    setupChromeProcess: function setupChromeProcess(testing) {
> +    this._log.trace("setupChromeProcess - Setting Telemetry within the Chrome process.");

Nit: "Setting up" or just drop the description.

@@ +1298,5 @@
>    observe: function (aSubject, aTopic, aData) {
> +    // The logger might still be not available at this point.
> +    if (this._log !== null) {
> +      this._log.trace("observe - " + aTopic + " notified.");
> +    }

You could just use:
if (!this._log) {
  this._log = Log.repository.getLogger(...);
}

This probably won't log visibly until we set it up, but that's fine.

Comment 7

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8552385 [details] [diff] [review]
bug1122049.patch - v3

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

::: toolkit/components/telemetry/tests/unit/test_TelemetryLog.js
@@ +27,5 @@
>  
>  function run_test()
>  {
> +  // Make sure log is initialised.
> +  yield TelemetryPing.setup();

Ah, hm. It would be good if we don't need to call that in every test to configure the logging.
We also would want to set the prefs for the tests so we always log Telemetry properly in the telemetry tests.

We could add that to head.js:
* First setup the log.level and .dump prefs
* Then e.g. call a TelemetryPing.initLogging() (documented as test-only) that ends up calling the configureLogging()

Comment 8

[Georg Fritzsche [:gfritzsche]]

Nearly forgot - it would be nice to initialize Impl._log with this:
Log.repository.getLoggerWithMessagePrefix(LOGGER_NAME, "TelemetryPing::")

That way, logging like this:
> this._log("foo - bar");
results in log messages like this:
> Toolkit.Telemetry   TRACE   TelemetryPing::foo - bar

Comment 9

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v4

Thank you Georg for your time reviewing this. This patch:

- Makes configureLogging a non member function
- Initialises the logging for the tests
- Makes use of |getLoggerWithMessagePrefix|

As for the last point, I've noticed that you *need* to initialise the logger using |getLogger| (call addAppender on the returned logger), as it does not work with the proxy logger returned from |getLoggerWithMessagePrefix|.

Comment 10

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v4

Sorry, I forgot to remove the pending test configuration in |test_TelemetryLog| in the previous patch.

Comment 11

[Alessio Placitelli [:Dexter]]

A try push for the patch: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b40c185f56e6

Comment 12

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v5

This patch makes sure logging gets initialised for tests using TelemetryPing, to address test failures from the previous try-push.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a26042872bb7

Comment 13

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8554264 [details] [diff] [review]
bug1122049.patch - v5

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

::: browser/experiments/test/xpcshell/test_conditions.js
@@ +51,5 @@
>  add_task(function* test_setup() {
> +  let TelemetryPing =
> +    Cu.import("resource://gre/modules/TelemetryPing.jsm", {}).TelemetryPing;
> +
> +  // We need to initialise Telemetry logging before making any call to Telemetry.

Why? If we are working with uninitialized instances then we should fix that.

::: toolkit/components/telemetry/TelemetryPing.jsm
@@ +265,5 @@
> +  /**
> +   * Used only for testing purposes.
> +   */
> +  initLogging: function() {
> +    return Impl.initLogging();

This should only need to call configureLogging().
Do any tests need more than this? That implies they call functions of TelemetryPing before it was properly initialized.

@@ +1029,5 @@
>      if (!this._initialized)
>        return;
>      Services.obs.addObserver(this, "cycle-collector-begin", false);
>      Services.obs.addObserver(this, "idle-daily", false);
> +    Preferences.observe(PREF_BRANCH + "log.", configureLogging, this);

* We could just use a |const PREF_BRANCH_LOG|.
* Remove the last argument.
* Optional: We could keep setup for the log pref observer out of this instance.

Comment 14

[Georg Fritzsche [:gfritzsche]]

Side-note: I can't get both this and bug 1123384 applied without conflicts, no matter what order i try.

Comment 15

[Alessio Placitelli [:Dexter]]

Thanks for your time reviewing this!

> ::: browser/experiments/test/xpcshell/test_conditions.js
> @@ +51,5 @@
> >  add_task(function* test_setup() {
> > +  let TelemetryPing =
> > +    Cu.import("resource://gre/modules/TelemetryPing.jsm", {}).TelemetryPing;
> > +
> > +  // We need to initialise Telemetry logging before making any call to Telemetry.
> 
> Why? If we are working with uninitialized instances then we should fix that.

It appears that some tests directly call |TelemetryPing.getPayload| (e.g. https://dxr.mozilla.org/mozilla-central/source/toolkit/modules/tests/xpcshell/test_TelemetryTimestamps.js#17 ), without doing any prior initialisation. This only happens with the tests. I think we should just make sure logging is initialised in those places: were you thinking of something different?

> ::: toolkit/components/telemetry/TelemetryPing.jsm
> @@ +265,5 @@
> > +  /**
> > +   * Used only for testing purposes.
> > +   */
> > +  initLogging: function() {
> > +    return Impl.initLogging();
> 
> This should only need to call configureLogging().
> Do any tests need more than this? That implies they call functions of
> TelemetryPing before it was properly initialized.

Good point. No, tests other then the ones in telemetry/tests just seem to call TelemetryPing.getPayload, so calling TelemetryPing.initLogging should be more than enough.

Unfortunately this and bug 1123384 both change TelemetryPing: I can rebase this patch on the ones from 1123384, which would make things easier. What do you think?

Comment 16

[Georg Fritzsche [:gfritzsche]]

(In reply to Alessio Placitelli [:Dexter] from comment #15)
> > ::: browser/experiments/test/xpcshell/test_conditions.js
> > @@ +51,5 @@
> > >  add_task(function* test_setup() {
> > > +  let TelemetryPing =
> > > +    Cu.import("resource://gre/modules/TelemetryPing.jsm", {}).TelemetryPing;
> > > +
> > > +  // We need to initialise Telemetry logging before making any call to Telemetry.
> > 
> > Why? If we are working with uninitialized instances then we should fix that.
> 
> It appears that some tests directly call |TelemetryPing.getPayload| (e.g.
> https://dxr.mozilla.org/mozilla-central/source/toolkit/modules/tests/
> xpcshell/test_TelemetryTimestamps.js#17 ), without doing any prior
> initialisation. This only happens with the tests. I think we should just
> make sure logging is initialised in those places: were you thinking of
> something different?
> 
> > ::: toolkit/components/telemetry/TelemetryPing.jsm
> > @@ +265,5 @@
> > > +  /**
> > > +   * Used only for testing purposes.
> > > +   */
> > > +  initLogging: function() {
> > > +    return Impl.initLogging();
> > 
> > This should only need to call configureLogging().
> > Do any tests need more than this? That implies they call functions of
> > TelemetryPing before it was properly initialized.
> 
> Good point. No, tests other then the ones in telemetry/tests just seem to
> call TelemetryPing.getPayload, so calling TelemetryPing.initLogging should
> be more than enough.

With the other patch you will presumably run into the same problem with TelemetrySession.
The same problem applies: its using an uninitialized instance. Lets just properly initialize it instead of worrying about logging specifically.

> Unfortunately this and bug 1123384 both change TelemetryPing: I can rebase
> this patch on the ones from 1123384, which would make things easier. What do
> you think?

As they are conflicting, you can't develop them independently.
I don't mind what order they are in, but they need a defined order :)

Comment 17

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v6 (stacks on bug 1123384)

This patch builds upon bug 1123384. Telemetry initialisation in test is moved to that bug.

Comment 18

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v7 (stacks on bug 1123384)

Updated the patch to apply correctly on the one from bug 1123384.

Comment 19

[Alessio Placitelli [:Dexter]]

This is a trypush for this and bug 1123384: https://treeherder.mozilla.org/#/jobs?repo=try&revision=1577731ec364

Comment 20

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8554502 [details] [diff] [review]
bug1122049.patch - v7 (stacks on bug 1123384)

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

::: toolkit/components/telemetry/TelemetryPing.jsm
@@ +26,4 @@
>  const PREF_SERVER = PREF_BRANCH + "server";
>  const PREF_ENABLED = PREF_BRANCH + "enabled";
> +const PREF_LOG_LEVEL = PREF_BRANCH + "log.level";
> +const PREF_LOG_DUMP = PREF_BRANCH + "log.dump";

PREF_BRANCH_LOG + ...

Comment 21

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v8 (stacks on bug 1123384)

This patch takes care of the Nit Georg pointed out.

Comment 22

[Georg Fritzsche [:gfritzsche]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b07179c96da7

Comment 23

[Ryan VanderMeulen [:RyanVM]]

Backed out for the same checktest failures that were all over your Try push in comment 19. Additionally, it also blew up mochitests. Please verify the results of your Try pushes before blindly pushing to inbound to avoid inconveniencing all the other developers waiting on the closed tree to reopen.

https://hg.mozilla.org/integration/mozilla-inbound/rev/eb6110f55c31

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=b07179c96da7 shows all the various failures this caused.

Comment 24

[Alessio Placitelli [:Dexter]]

Attachment: bug1122049.patch - v9

This patch fixes the bustages in the tests. A new try push was done: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ff6aa620001a

Comment 25

[Alessio Placitelli [:Dexter]]

The only failure which persists on retriggering is on the "Mulet Linux x64 opt", "dom/base/test/test_hasFeature.html". The similar jobs tab shows other jobs failing for the same reason so I think it's not due to the logging here.

Comment 26

[Georg Fritzsche [:gfritzsche]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/fe450d7aa893

Comment 27

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/fe450d7aa893