1134268 - TelemetrySession shutdown fails to save pending pings.

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Alessio Placitelli [:Dexter]]

When shutting down, TelemetrySession.jsm fails to save pending pings ("saved-session").

The following is a log trace of the problem:

1424280489386   Toolkit.Telemetry       TRACE   TelemetrySession::savePendingPings
1424280489397   Toolkit.Telemetry       TRACE   TelemetrySession::getSessionPayload - reason: saved-session, clearSubsession: true
1424280489409   Toolkit.Telemetry       TRACE   TelemetrySession::getSimpleMeasurements
1424280489477   Toolkit.Telemetry       TRACE   TelemetrySession::getMetadata - Reason saved-session
1424280489487   Toolkit.Telemetry       TRACE   TelemetrySession::getFlashVersion
1424280492299   Toolkit.Telemetry       TRACE   TelemetrySession::assemblePayloadWithMeasurements -reason: saved-session, submitting subsession data: false
1424280492308   Toolkit.Telemetry       TRACE   TelemetrySession::getHistograms - subsession: false, clearSubsession: true
1424280492768   Toolkit.Telemetry       TRACE   TelemetrySession::getKeyedHistograms - subsession: false, clearSubsession: true
1424280492787   Toolkit.Telemetry       TRACE   TelemetrySession::getThreadHangStats
1424280492795   Toolkit.Telemetry       TRACE   TelemetrySession::getAddonHistograms
1424280492804   Toolkit.Telemetry       TRACE   TelemetrySession::_scheduleDailyTimer - now: Wed Feb 18 2015 18:28:12 GMT+0100 (ora solare Europa occidentale), scheduled: Thu Feb 19 2015 00:00:00 GMT+0100 (ora solare Europa occidentale)
1424280492829   Toolkit.Telemetry       TRACE   TelemetryPing::savePendingPings - Type main, Serverhttp://127.0.0.1:3785, aOptions {"retentionDays":14,"addClientId":true,"addEnvironment":true}
1424280492840   Toolkit.Telemetry       TRACE   TelemetryPing::assemblePing - Type main, Server http://127.0.0.1:3785, aOptions {"retentionDays":14,"addClientId":true,"addEnvironment":true}
JavaScript strict warning: resource://gre/modules/TelemetryEnvironment.jsm, line 900: ReferenceError: reference to undefined property this._log
WARNING: A blocker encountered an error while we were waiting.
          Blocker:  TelemetrySession: shutting down
          Phase: profile-before-change2
          State: (none)
WARNING: TypeError: this._log is undefined
WARNING: this.TelemetryEnvironment.getEnvironmentData@resource://gre/modules/TelemetryEnvironment.jsm:900:7
assemblePing@resource://gre/modules/TelemetryPing.jsm:328:14
savePendingPings@resource://gre/modules/TelemetryPing.jsm:423:12
this.TelemetryPing<.savePendingPings@resource://gre/modules/TelemetryPing.jsm:183:12
savePendingPings@resource://gre/modules/TelemetrySession.jsm:1069:12
Impl.shutdown@resource://gre/modules/TelemetrySession.jsm:1228:1
setupChromeProcess/<@resource://gre/modules/TelemetrySession.jsm:961:48
Barrier/this.client.addBlocker/promise</trigger@resource://gre/modules/AsyncShutdown.jsm:652:23
Barrier.prototype<._wait@resource://gre/modules/AsyncShutdown.jsm:790:7
Barrier.prototype<.wait@resource://gre/modules/AsyncShutdown.jsm:774:28
Spinner.prototype.observe@resource://gre/modules/AsyncShutdown.jsm:454:19

Comment 1

[Georg Fritzsche [:gfritzsche]]

Attachment: Sync shutdown via a shutdown barrier for TelemetryPing

Comment 2

[Georg Fritzsche [:gfritzsche]]

Attachment: Fix accessing potentially non-initialized logging

Trivial patch, i promise.

Comment 3

[Vladan Djeric (:vladan)]

Comment on attachment 8566622 [details] [diff] [review]
Fix accessing potentially non-initialized logging

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

::: toolkit/components/telemetry/TelemetryEnvironment.jsm
@@ +267,1 @@
>        throw new Error("Already shut down");

r+ for the fix

But do we really want to reject a promise here? Seems like shutdown should be an idempotent function. If you try to shut down a module that's already shut down, it's a success, not a failure.

Comment 4

[Georg Fritzsche [:gfritzsche]]

Attachment: Fixup TelemetryEnvironment shutdown if the module wasnt initialized.

Incorporated that suggestion as there is no reason to reject here.
Also added Cu.reportError() if we don't have a logger instance so that this error path still shows up somewhere.

Comment 5

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8566603 [details] [diff] [review]
Sync shutdown via a shutdown barrier for TelemetryPing

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

::: toolkit/components/telemetry/TelemetryPing.jsm
@@ +724,5 @@
>          this._initialized = false;
>          this._initStarted = false;
>        };
> +      return this._shutdownBarrier.wait().then(
> +               () => TelemetryEnvironment.shutdown().then(reset, reset));

Does the barrier itself block shutdown (in particular OS.File shutdown)?

::: toolkit/components/telemetry/TelemetrySession.jsm
@@ +943,5 @@
>        return Promise.resolve();
>      }
>  
> +    TelemetryPing.shutdown.addBlocker(
> +      "TelemetrySession: shutting down", () => this.shutdownChromeProcess());

Could you add a state? That's always useful for debugging purposes.

Comment 6

[Georg Fritzsche [:gfritzsche]]

Attachment: Fix and order Telemetry shutdown for TelemetryPing and TelemetrySession

I noticed that we are missing proper sync with the delayed init task in TelemetrySession too, so i expanded this to:
* Add a shutdown barrier for TelemetryPing and hang TelemetrySession off it. 
* Add AsyncShutdown state collection for TelemetryPing and TelemetrySession.
* Rework TelemetrySession chrome process shutdown to properly synchronize with the delayed init task.

Comment 7

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8567049 [details] [diff] [review]
Fix and order Telemetry shutdown for TelemetryPing and TelemetrySession

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

::: toolkit/components/telemetry/TelemetryPing.jsm
@@ +785,5 @@
>    get clientID() {
>      return this._clientID;
>    },
> +
> +  _getState: function() {

Nit: A comment explaining what this method does?

::: toolkit/components/telemetry/TelemetrySession.jsm
@@ +1433,5 @@
>      let filePath = OS.Path.join(dataDir, SESSION_STATE_FILE_NAME);
>      yield CommonUtils.writeJSON(obj, filePath);
>    }),
> +
> +  _getState: function() {

Nit: Here, too, a little doc.

Comment 8

[Georg Fritzsche [:gfritzsche]]

Attachment: Fix and order Telemetry shutdown for TelemetryPing and TelemetrySession

Addressed review comment.

Comment 9

[Georg Fritzsche [:gfritzsche]]

Attachment: Fixup TelemetryEnvironment shutdown if the module wasnt initialized.

Missed updating for the test fix.

Comment 10

[Georg Fritzsche [:gfritzsche]]

Attachment: Part 1 - Fix and order Telemetry shutdown for TelemetryPing and TelemetrySession

Comment 11

[Georg Fritzsche [:gfritzsche]]

Attachment: Part 2 - Fixup TelemetryEnvironment shutdown if the module wasnt initialized.

Comment 12

[Georg Fritzsche [:gfritzsche]]

Attachment: Part 1 - Fix and order Telemetry shutdown for TelemetryPing and TelemetrySession

Comment 13

[Georg Fritzsche [:gfritzsche]]

Pushed in: https://hg.mozilla.org/integration/fx-team/pushloghtml?changeset=b83c3fa8c80f

Comment 14

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/021492258f45
https://hg.mozilla.org/mozilla-central/rev/3b275220d414