1211222 - Telemetry attempts to send persisted pings at shutdown?

Status: RESOLVED WORKSFORME

(Toolkit :: Telemetry, defect)

Description

[Vladan Djeric (:vladan)]

Attachment: telemetryLog.txt

As I understand it, Telemetry should not be attempting to send data on shutdown.

STR:

0. Enable telemetry logging
1. Trigger some code that submits an external ping
2. Shut down Firefox and observe the console stdout. 

Notably I saw Telemetry trying to send the persisted external pings (in an m-c build):

INFO    TelemetrySend::_checkPendingPings - pending ping count: 3
ERROR   TelemetrySend::_doPing - error making request to http://127.0.0.1:8000/submit/telemetry/e052f17e-1faf-49ef-aa6b-addc0562f3ae/heartbeat/Firefox/44.0a1/default/20151003204654?v=4: error
ERROR   TelemetrySend::sendPersistedPings - failed to send ping e052f17e-1faf-49ef-aa6b-addc0562f3ae: {"isTrusted":true}
WARN    TelemetryStorage::_scanArchive - have seen this id before: e052f17e-1faf-49ef-aa6b-addc0562f3ae, overwrite: false

Note that the dummy gzipServer was listening on http://127.0.0.1:8000 but never received any requests.

Comment 1

[Vladan Djeric (:vladan)]

To reproduce this bug, you need to trigger shutdown almost immediately after triggering submitExternalPing

Comment 2

[Georg Fritzsche [:gfritzsche]]

This might just be the following scenario:
* the SendScheduler is still running
* shutdown cancels the outgoing requests here
* we wait for the scheduler to finish its current iteration

The log sounds like this might have been a really short session (<60sec or so)?

Alessio, can you try to check whether the shutdown behavior is proper?

Comment 3

[Alessio Placitelli [:Dexter]]

Yes, this is the scenario triggering that log: TelemetrySend.shutdown [1] is cancelling outgoing requests when closing Firefox on short sessions. We don't try to send newly submitted pings on shutdown.

I've double checked locally with current m-c and a local gzipServer: the pings are not reaching the server due to the shutdown process.

[1] - https://dxr.mozilla.org/mozilla-central/rev/3d7532ce81ac571962abc3b99582fe7f5d685192/toolkit/components/telemetry/TelemetrySend.jsm#631

Comment 4

[Alessio Placitelli [:Dexter]]

Attachment: shutdown_bug1211222.txt

I've filtered out unrelated log lines from this file: as you can see, the shutdown sequence starts (TelemetryController.shutdown()). Shortly after, |TelemetrySend::Scheduler::shutdown| is called and then we start cancelling outgoing ping requests.

Comment 5

[Alessio Placitelli [:Dexter]]

Vladan, would you mind posting more log? Maybe "Trace" level so we can cross check.

Comment 6

[Alessio Placitelli [:Dexter]]

The pref to change the log level is "toolkit.telemetry.log.level", just set it to "Trace" (string).
I would need the log from |TelemetryyController::shutdown|, on.

Comment 7

[Vladan Djeric (:vladan)]

Attachment: shutdownTrace.txt

Comment 8

[Alessio Placitelli [:Dexter]]

Thanks Vladan. I confirm this is what explained in comment 2 and comment 4.

Comment 9

[Vladan Djeric (:vladan)]

Ok this sounds like a non-issue, I'll mark this WORKSFORME