Closed Bug 1450204 Opened 6 years ago Closed 6 years ago

Intermittent toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_sendCheckOverride - [test_sendCheckOverride : 257] A promise chain failed to handle a rejection: Win error 2 during operation delete on file

Categories

(Toolkit :: Telemetry, defect, P1)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla61
Tracking Flags:
Tracking Status
firefox61 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: Dexter)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:other])

Attachments

(1 file)

Bug 1450204 - Reset the ping id genrator after each test.
59 bytes, text/x-review-board-request
chutten
: review+
Details 
Filed by: shindli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=171175367&repo=autoland

https://queue.taskcluster.net/v1/task/PWA37W1tSjy63MJWPtTIXg/runs/0/artifacts/public/logs/live_backing.log

07:11:43  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | xpcshell return code: 0
This seems to be related, somehow, to 1448861
See Also: → 1448861
Summary: Intermittent toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | xpcshell return code: 0 → Intermittent toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_sendCheckOverride - [test_sendCheckOverride : 257] A promise chain failed to handle a rejection: Win error 2 during operation delete on file
See Also: → 1450319
in bug 1450319, Eliza did some retriggers:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=runnable&filter-resultStatus=success&filter-resultStatus=running&filter-resultStatus=pending&filter-searchStr=Windows%207%20opt-xpcshell&tochange=457b9e70da837921fb5e6b12682b5c0c7604dc6e&fromchange=8332666d3935bc0ff3ec894bd1e0907f5c61a844&selectedJob=170622080


the failure started in one of the 7 bugs that landed together:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?changeset=457b9e70da83

:gfritzsche, could you look at that range of 7 bugs (1 is just a test manifest change for web-platform-tests- so 6 bugs) and help pinpoint the root cause?

My best guess is one of these 2:
ea1a3efdde8b	Jan-Erik Rediger — Bug 1443603 - Stop sending `saved-session` pings from Firefox Desktop r=chutten
38646fa333aa	Kyle Zhou — Bug 1442061 - Remove content process in memory_total histogram's "record_in_processes" r=chutten
Flags: needinfo?(gfritzsche)
Alessio is currently looking into this set of bugs to see what's going on.
Flags: needinfo?(gfritzsche) → needinfo?(alessio.placitelli)
Assignee: nobody → alessio.placitelli
Flags: needinfo?(alessio.placitelli)
Priority: P5 → P1
(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #4)
> in bug 1450319, Eliza did some retriggers:
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-
> resultStatus=testfailed&filter-resultStatus=busted&filter-
> resultStatus=exception&filter-resultStatus=runnable&filter-
> resultStatus=success&filter-resultStatus=running&filter-
> resultStatus=pending&filter-searchStr=Windows%207%20opt-
> xpcshell&tochange=457b9e70da837921fb5e6b12682b5c0c7604dc6e&fromchange=8332666
> d3935bc0ff3ec894bd1e0907f5c61a844&selectedJob=170622080
> 
> 
> the failure started in one of the 7 bugs that landed together:
> https://hg.mozilla.org/integration/mozilla-inbound/
> pushloghtml?changeset=457b9e70da83

Thanks for pointing us to this, Joel!

> My best guess is one of these 2:
> ea1a3efdde8b	Jan-Erik Rediger — Bug 1443603 - Stop sending `saved-session`
> pings from Firefox Desktop r=chutten

Your best guess, according to my current theory, is correct :) By having a closer look at the log of this and the other related failures, looks like bug 1443603 hid another test-only problem: different tests were generating pings with the same UUID. For this reason, the different tests (in the same file) were competing for deletion/sending them. The "saved-session" ping was an additional ping being saved at shutdown that mitigated the problem: after deleting one ping, this was saved, then deleted again.

Here's some context from the logs:

> Toolkit.Telemetry	TRACE	TelemetryHealthPing::::_assemblePayload()"
> Toolkit.Telemetry	TRACE	TelemetryHealthPing::::_clearData()"
> Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: health, aOptions: {"addClientId":true,"usePingSender":true,"addEnvironment":false}"
> Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type health, aOptions {"addClientId":true,"usePingSender":true,"addEnvironment":false}"
> Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: 93bd0011-2c8f-4e1c-bee0-f00000000004"
> Toolkit.Telemetry	WARN	TelemetryStorage::saveArchivedPing - overwriting older ping with the same id"
> Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: 93bd0011-2c8f-4e1c-bee0-f00000000004, options: {"usePingSender":true}"
> nfqobh\\datareporting\\archived\\2010-02\\1265029740000.93bd0011-2c8f-4e1c-bee0-f00000000004.health.jsonlz4"
> Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: c:\\users\\genericworker\\appdata\\local\\temp\\xpc-profile-nfqobh\\saved-telemetry-pings\\93bd0011-2c8f-4e1c-bee0-f00000000004"
> Toolkit.Telemetry	TRACE	TelemetryStorage::savePendingPing - saved ping with id 93bd0011-2c8f-4e1c-bee0-f00000000004"
> 
> ...
>
> Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: main, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":false}"
> Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":false}"
> Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: 93bd0011-2c8f-4e1c-bee0-f00000000004"
> Toolkit.Telemetry	WARN	TelemetryStorage::saveArchivedPing - overwriting older ping with the same id"
> Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: 93bd0011-2c8f-4e1c-bee0-f00000000004, options: {"usePingSender":false}"
> Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
> Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
> Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - can't send ping now, persisting to disk - canSendNow: false"
> Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: c:\\users\\genericworker\\appdata\\local\\temp\\xpc-profile-nfqobh\\datareporting\\archived\\2010-02\\1265029740000.93bd0011-2c8f-4e1c-bee0-f00000000004.main.jsonlz4"
> Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: c:\\users\\genericworker\\appdata\\local\\temp\\xpc-profile-nfqobh\\saved-telemetry-pings\\93bd0011-2c8f-4e1c-bee0-f00000000004"
> Toolkit.Telemetry	TRACE	PingServer::defaultPingHandler() - POST http://localhost:64744/submit/telemetry/93bd0011-2c8f-4e1c-bee0-f00000000004/health///default/"
> PID 5436 | WARNING: A blocker encountered an error while we were waiting.
> PID 5436 |           Blocker:  Waiting for ping task
> PID 5436 |           Phase: TelemetryController: Waiting for pending ping activity
> PID 5436 |           State: (none)
> PID 5436 | WARNING: Win error 2 during operation delete on file c:\\users\\genericworker\\appdata\\local\\temp\\xpc-profile-nfqobh\\saved-telemetry-pings\\93bd0011-2c8f-4e1c-bee0-f00000000004 (The system cannot find the file specified.
> PID 5436 | )
> PID 5436 | WARNING:

As you can see, the health ping is generated with the "93bd0011-2c8f-4e1c-bee0-f00000000004" UUID. Then it's sent (and deleted from the disk). Before it's sent, the main ping is saved with the same id. After the "health ping 93bd0011-2c8f-4e1c-bee0-f00000000004" is sent, we deleted it. But the "main ping 93bd0011-2c8f-4e1c-bee0-f00000000004" doesn't know about that, so it complains :) Weird, ya?

Here's the try push that reproduces the issue:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0d171978eba121f48fb1407a2b8878ff796a33de&selectedJob=171793855

And here's a tentative try push with the patch to fix this problem:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=bc02dfe2d7cca8c4afa51cafd07d1b0282a8c87b&selectedJob=171677963
Comment on attachment 8964863 [details]
Bug 1450204 - Reset the ping id genrator after each test.

https://reviewboard.mozilla.org/r/233600/#review239382

Ugh. I wish there were a clean way to return all Policy back to initial state after each test. The closest I could find was registerCleanupFunction but according to the docs that's per-file, not per test.
Attachment #8964863 - Flags: review?(chutten) → review+
Pushed by alessio.placitelli@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/3af6db57d625
Reset the ping id genrator after each test. r=chutten
https://hg.mozilla.org/mozilla-central/rev/3af6db57d625
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox61: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Whiteboard: [stockwell fixed:other]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: