1397293 - Fix Telemetry sending pings late after network shutdown

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P1)

Description

[Georg Fritzsche [:gfritzsche]]

Per bug 1393731, comment 6:
> Looking locally, at my about:telemetry page, i see a common pattern:
> - one health ping with reason "immediate"
> - followed after <1sec by a "shutdown" health ping
> 
> We should be able to confirm if this common with a longitudinal, per-client analysis.
> If so, that would (again) point to that we are trying to send pings after the
> Firefox network stack already shut down.

This seems a concrete issue that we need to address.
For potential Telemetry risk we may hold changes here back to 58.

Comment 1

[Georg Fritzsche [:gfritzsche]]

We have multiple network related observer notifications, these are what i found:
"profile-change-net-teardown"
"network:offline-status-changed" with data=="offline"
"network:offline-about-to-go-offline"

Andrea, do you know which one to prefer in our situation?
Right now we specifically want to avoid/stop sending activity from Telemetry when the browser shuts down.

We may extend this later to cover temporary network availability too, but this is out of scope for now.

Comment 2

[Georg Fritzsche [:gfritzsche]]

Patrick, do you know about the questions in comment 1?

Comment 3

[Daniel Stenberg [:bagder]]

 "profile-change-net-teardown" is the shutdown notification to use which signals that shutdown is now in progress. The other two are for when Firefox is "merely" going offline.

Comment 4

[Chris H-C :chutten]

Attachment: bug 1397293 - Don't try to send Telemetry after net shutdown

Once networking starts tearing down, our attempts to use XHR to send pings
will fail. This might contibute to high intermittent send failures reported
in the wild. So let's not even try.

But, let's be sure to mention when we decide not to try so we can ensure the
numbers line up before and after.

Review commit: https://reviewboard.mozilla.org/r/183578/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/183578/

Comment 5

[Alessio Placitelli [:Dexter]]

Comment on attachment 8912205 [details]
bug 1397293 - Don't try to send Telemetry after net shutdown

https://reviewboard.mozilla.org/r/183578/#review188764

::: toolkit/components/telemetry/Histograms.json:7272
(Diff revision 1)
>        "eUnreachable",
>        "eChannelOpen",
>        "eRedirect",
>        "abort",
> -      "timeout"
> +      "timeout",
> +      "eTooLate"

Mh, since this is a categorical histogram, do we need to rename it when adding labels? See [doc](https://firefox-source-docs.mozilla.org/toolkit/components/telemetry/telemetry/collection/histograms.html#categorical)

::: toolkit/components/telemetry/TelemetrySend.jsm:1088
(Diff revision 1)
>        // We can't send the pings to the server, so don't try to.
>        this._log.trace("_doPing - Can't send ping " + ping.id);
>        return Promise.resolve();
>      }
>  
> +    if (this._tooLateToSend) {

Can we add test coverage for this in test_TelemetrySend (or a new file)? We might want to check that:

- Pings still get persisted and will be sent next time telemetry starts.
- The histogram contains the right values.

Comment 6

[Chris H-C :chutten]

Comment on attachment 8912205 [details]
bug 1397293 - Don't try to send Telemetry after net shutdown

https://reviewboard.mozilla.org/r/183578/#review188764

> Mh, since this is a categorical histogram, do we need to rename it when adding labels? See [doc](https://firefox-source-docs.mozilla.org/toolkit/components/telemetry/telemetry/collection/histograms.html#categorical)

Nope! So long as I keep under the 50-bucket default, we're cool. See: Bug 1374508, amongst others.

> Can we add test coverage for this in test_TelemetrySend (or a new file)? We might want to check that:
> 
> - Pings still get persisted and will be sent next time telemetry starts.
> - The histogram contains the right values.

I tried adding a test and had difficulty clearing the number of pending pings. I'll try again.

Comment 7

[Alessio Placitelli [:Dexter]]

Comment on attachment 8912205 [details]
bug 1397293 - Don't try to send Telemetry after net shutdown

https://reviewboard.mozilla.org/r/183578/#review188764

> Nope! So long as I keep under the 50-bucket default, we're cool. See: Bug 1374508, amongst others.

Nice, I didn't know that!

> I tried adding a test and had difficulty clearing the number of pending pings. I'll try again.

Cool, let me know if there's anything I can do to help with that.

Comment 8

[Chris H-C :chutten]

Attachment: bug 1397293 - Test TelemetrySend tooLateToSend

Review commit: https://reviewboard.mozilla.org/r/183694/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/183694/

Comment 9

[Chris H-C :chutten]

Attachment: bug 1397293 - Suppress TelemetryStopwatch errors in TelemetrySend tests

Review commit: https://reviewboard.mozilla.org/r/183696/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/183696/

Comment 10

[Alessio Placitelli [:Dexter]]

Comment on attachment 8912367 [details]
bug 1397293 - Suppress TelemetryStopwatch errors in TelemetrySend tests

https://reviewboard.mozilla.org/r/183696/#review189064

::: toolkit/components/telemetry/tests/unit/test_TelemetrySend.js:621
(Diff revision 1)
>    Services.prefs.setBoolPref(TelemetryUtils.Preferences.FhrUploadEnabled, origFhrUploadEnabled);
>  });
>  
>  add_task(async function cleanup() {
>    await PingServer.stop();
> +  TelemetryStopwatch.setTestModeEnabled(false);

AFAIK, that's not needed: these tests are executed in a separated environment compared to the other files.

Comment 11

[Alessio Placitelli [:Dexter]]

Comment on attachment 8912366 [details]
bug 1397293 - Test TelemetrySend tooLateToSend

https://reviewboard.mozilla.org/r/183694/#review189068

Comment 12

[Alessio Placitelli [:Dexter]]

Comment on attachment 8912205 [details]
bug 1397293 - Don't try to send Telemetry after net shutdown

https://reviewboard.mozilla.org/r/183578/#review189070

Thanks for addressing the feedback!

Comment 13

[Chris H-C :chutten]

Comment on attachment 8912367 [details]
bug 1397293 - Suppress TelemetryStopwatch errors in TelemetrySend tests

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/183696/diff/1-2/

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e663536181b0
Don't try to send Telemetry after net shutdown r=Dexter
https://hg.mozilla.org/integration/autoland/rev/49ebf04b8291
Test TelemetrySend tooLateToSend r=Dexter
https://hg.mozilla.org/integration/autoland/rev/747a89f3dead
Suppress TelemetryStopwatch errors in TelemetrySend tests r=Dexter

Comment 15

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/e663536181b0
https://hg.mozilla.org/mozilla-central/rev/49ebf04b8291
https://hg.mozilla.org/mozilla-central/rev/747a89f3dead

Comment 16

[Chris H-C :chutten]

Comment on attachment 8912205 [details]
bug 1397293 - Don't try to send Telemetry after net shutdown

Approval Request Comment
[Feature/Bug causing the regression]: None. Long-standing issue with Telemetry
[User impact if declined]: Twice as many "health" pings will be sent by users.
[Is this code covered by automated tests?]: Yes, patch 2.
[Has the fix been verified in Nightly?]: I've seen health ping volumes decrease[1] and eTooLate numbers increase[2] which is pretty good evidence in support of this working.
[Needs manual test from QE? If yes, steps to reproduce]: I don't think so.
[List of other uplifts needed for the feature/fix]: The other patches in this bug
[Is the change risky?]: No.
[Why is the change risky/not risky?]: Instead of trying to send a net request at a time we know it will fail, we don't try.
[String changes made/needed]: None.

[1]: https://screenshots.firefoxusercontent.com/images/af909e5a-3965-487e-a7b8-d068f5ae0146.png
[2]: https://mzl.la/2ynjCru

Comment 17

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8912205 [details]
bug 1397293 - Don't try to send Telemetry after net shutdown

As much as I'd like to take this change in 57, we are trying to limit the uplifts to severe recent regressions due to Quantum, Photon, Stylo work. This uplift doesn't meet that bar. Let this fix ride the 58 train.