Closed Bug 1122049 Opened 7 years ago Closed 7 years ago

Add logging to Telemetry.

Categories

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

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED
Firefox 38

People

(Reporter: Dexter, Assigned: Dexter)

References

Details

Attachments

(1 file, 10 obsolete files)

27.63 KB, patch
Details | Diff | Splinter Review
We need to add logging to telemetry (Log.jsm), plus the related config & preferences.
Assignee: nobody → alessio.placitelli
This patch adds logging to TelemetryPing.
Attachment #8551780 - Flags: review?(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.
Attachment #8551780 - Flags: review?(gfritzsche)
Attached patch bug1122049.patch (obsolete) — Splinter Review
Thanks for the review! This patch implements the suggested changes.
Attachment #8551780 - Attachment is obsolete: true
Attachment #8551900 - Flags: review?(gfritzsche)
OS: Windows 7 → All
Hardware: x86_64 → All
Version: unspecified → Trunk
Attached patch bug1122049.patch - v2 (obsolete) — Splinter Review
Attachment #8551900 - Attachment is obsolete: true
Attachment #8551900 - Flags: review?(gfritzsche)
Attachment #8551902 - Flags: review?(gfritzsche)
Attached patch bug1122049.patch - v3 (obsolete) — Splinter Review
Makes sure logging is initialised during tests.
Attachment #8551902 - Attachment is obsolete: true
Attachment #8551902 - Flags: review?(gfritzsche)
Attachment #8552385 - Flags: review?(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.
Attachment #8551902 - Attachment is obsolete: false
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()
Attachment #8552385 - Flags: review?(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
Attached patch bug1122049.patch - v4 (obsolete) — Splinter Review
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|.
Attachment #8551902 - Attachment is obsolete: true
Attachment #8552385 - Attachment is obsolete: true
Attachment #8554241 - Flags: review?(gfritzsche)
Attached patch bug1122049.patch - v4 (obsolete) — Splinter Review
Sorry, I forgot to remove the pending test configuration in |test_TelemetryLog| in the previous patch.
Attachment #8554241 - Attachment is obsolete: true
Attachment #8554241 - Flags: review?(gfritzsche)
Attachment #8554242 - Flags: review?(gfritzsche)
Attached patch bug1122049.patch - v5 (obsolete) — Splinter Review
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
Attachment #8554242 - Attachment is obsolete: true
Attachment #8554242 - Flags: review?(gfritzsche)
Attachment #8554264 - Flags: review?(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.
Attachment #8554264 - Flags: review?(gfritzsche)
Side-note: I can't get both this and bug 1123384 applied without conflicts, no matter what order i try.
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?
Flags: needinfo?(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 :)
Flags: needinfo?(gfritzsche)
This patch builds upon bug 1123384. Telemetry initialisation in test is moved to that bug.
Attachment #8554264 - Attachment is obsolete: true
Attachment #8554473 - Flags: review?(gfritzsche)
Updated the patch to apply correctly on the one from bug 1123384.
Attachment #8554473 - Attachment is obsolete: true
Attachment #8554473 - Flags: review?(gfritzsche)
Attachment #8554502 - Flags: review?(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 + ...
Attachment #8554502 - Flags: review?(gfritzsche) → review+
Status: NEW → ASSIGNED
This patch takes care of the Nit Georg pointed out.
Attachment #8554502 - Attachment is obsolete: true
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.
This patch fixes the bustages in the tests. A new try push was done: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ff6aa620001a
Attachment #8555774 - Attachment is obsolete: true
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.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/fe450d7aa893
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 38
Product: Firefox Health Report → Firefox Health Report Graveyard
You need to log in before you can comment on or make changes to this bug.