Closed Bug 1601893 Opened 5 years ago Closed 5 years ago

Perma Release TEST-UNEXPECTED-FAIL | services/settings/test/unit/test_attachments_downloader.js | xpcshell return code: 0 when Gecko 72 merges to Release on 2019-12-30

Categories

(Firefox :: Remote Settings Client, defect)

defect
Not set
normal

Tracking

()

VERIFIED FIXED
Firefox 73
Tracking Status
firefox-esr68 --- unaffected
firefox71 --- unaffected
firefox72 + verified
firefox73 + fixed

People

(Reporter: malexandru, Assigned: leplatrem)

Details

(Keywords: regression)

Attachments

(1 file)

Beta as Release simulation: https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=279811324&revision=c79c000577560644752633916daa20d40011256a&searchStr=%28x&group_state=expanded

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=279811324&repo=try&lineNumber=2815

[task 2019-12-05T15:23:16.434Z] 15:23:16 INFO - TEST-PASS | services/settings/test/unit/test_attachments_downloader.js | test_delete_removes_local_file - [test_delete_removes_local_file : 195] true == true
[task 2019-12-05T15:23:16.435Z] 15:23:16 INFO - (xpcshell/head.js) | test run_next_test 14 pending (2)
[task 2019-12-05T15:23:16.435Z] 15:23:16 INFO - (xpcshell/head.js) | test test_delete_removes_local_file finished (2)
[task 2019-12-05T15:23:16.436Z] 15:23:16 INFO - services/settings/test/unit/test_attachments_downloader.js | Starting clear_state
[task 2019-12-05T15:23:16.436Z] 15:23:16 INFO - (xpcshell/head.js) | test clear_state pending (2)
[task 2019-12-05T15:23:16.436Z] 15:23:16 INFO - (xpcshell/head.js) | test run_next_test 14 finished (2)
[task 2019-12-05T15:23:16.437Z] 15:23:16 INFO - (xpcshell/head.js) | test run_next_test 15 pending (2)
[task 2019-12-05T15:23:16.437Z] 15:23:16 INFO - (xpcshell/head.js) | test clear_state finished (2)
[task 2019-12-05T15:23:16.437Z] 15:23:16 INFO - services/settings/test/unit/test_attachments_downloader.js | Starting test_downloader_is_accessible_via_client
[task 2019-12-05T15:23:16.438Z] 15:23:16 INFO - (xpcshell/head.js) | test test_downloader_is_accessible_via_client pending (2)
[task 2019-12-05T15:23:16.438Z] 15:23:16 INFO - (xpcshell/head.js) | test run_next_test 15 finished (2)
[task 2019-12-05T15:23:16.439Z] 15:23:16 INFO - TEST-PASS | services/settings/test/unit/test_attachments_downloader.js | test_downloader_is_accessible_via_client - [test_downloader_is_accessible_via_client : 204] "file:///tmp/xpc-profile-7cAv1n/settings/main/some-collection/test_file.pem" == "file:///tmp/xpc-profile-7cAv1n/settings/main/some-collection/test_file.pem"
[task 2019-12-05T15:23:16.439Z] 15:23:16 INFO - (xpcshell/head.js) | test run_next_test 16 pending (2)
[task 2019-12-05T15:23:16.439Z] 15:23:16 INFO - (xpcshell/head.js) | test test_downloader_is_accessible_via_client finished (2)
[task 2019-12-05T15:23:16.440Z] 15:23:16 INFO - services/settings/test/unit/test_attachments_downloader.js | Starting clear_state
[task 2019-12-05T15:23:16.440Z] 15:23:16 INFO - (xpcshell/head.js) | test clear_state pending (2)
[task 2019-12-05T15:23:16.441Z] 15:23:16 INFO - (xpcshell/head.js) | test run_next_test 16 finished (2)
[task 2019-12-05T15:23:16.441Z] 15:23:16 INFO - (xpcshell/head.js) | test run_next_test 17 pending (2)
[task 2019-12-05T15:23:16.441Z] 15:23:16 INFO - (xpcshell/head.js) | test clear_state finished (2)
[task 2019-12-05T15:23:16.442Z] 15:23:16 INFO - services/settings/test/unit/test_attachments_downloader.js | Starting
[task 2019-12-05T15:23:16.442Z] 15:23:16 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-12-05T15:23:16.442Z] 15:23:16 INFO - (xpcshell/head.js) | test run_next_test 17 finished (2)
[task 2019-12-05T15:23:16.443Z] 15:23:16 WARNING - TEST-UNEXPECTED-FAIL | services/settings/test/unit/test_attachments_downloader.js | - parent must be in snapshot. Has []. - false == true
[task 2019-12-05T15:23:16.443Z] 15:23:16 INFO - resource://testing-common/TelemetryTestUtils.jsm:assertEvents:138
[task 2019-12-05T15:23:16.444Z] 15:23:16 INFO - /builds/worker/workspace/build/tests/xpcshell/tests/services/settings/test/unit/test_attachments_downloader.js:null:231
[task 2019-12-05T15:23:16.444Z] 15:23:16 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:246
[task 2019-12-05T15:23:16.444Z] 15:23:16 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:573
[task 2019-12-05T15:23:16.445Z] 15:23:16 INFO - -e:null:1
[task 2019-12-05T15:23:16.446Z] 15:23:16 INFO - exiting test
[task 2019-12-05T15:23:16.446Z] 15:23:16 INFO - Unexpected exception NS_ERROR_ABORT:
[task 2019-12-05T15:23:16.447Z] 15:23:16 INFO - _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:791:20
[task 2019-12-05T15:23:16.447Z] 15:23:16 INFO - do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:892:5
[task 2019-12-05T15:23:16.447Z] 15:23:16 INFO - Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:67:21
[task 2019-12-05T15:23:16.448Z] 15:23:16 INFO - proto.report@resource://testing-common/Assert.jsm:233:10
[task 2019-12-05T15:23:16.448Z] 15:23:16 INFO - proto.ok@resource://testing-common/Assert.jsm:259:10
[task 2019-12-05T15:23:16.448Z] 15:23:16 INFO - assertEvents@resource://testing-common/TelemetryTestUtils.jsm:138:12
[task 2019-12-05T15:23:16.453Z] 15:23:16 INFO - @/builds/worker/workspace/build/tests/xpcshell/tests/services/settings/test/unit/test_attachments_downloader.js:231:22
[task 2019-12-05T15:23:16.454Z] 15:23:16 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:246:6
[task 2019-12-05T15:23:16.455Z] 15:23:16 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:573:5
[task 2019-12-05T15:23:16.456Z] 15:23:16 INFO - @-e:1:1
[task 2019-12-05T15:23:16.457Z] 15:23:16 INFO - exiting test
[task 2019-12-05T15:23:16.458Z] 15:23:16 INFO - <<<<<<<
[task 2019-12-05T15:23:16.458Z] 15:23:16 INFO - INFO | Result summary:
[task 2019-12-05T15:23:16.459Z] 15:23:16 INFO - INFO | Passed: 678
[task 2019-12-05T15:23:16.460Z] 15:23:16 WARNING - INFO | Failed: 1
[task 2019-12-05T15:23:16.461Z] 15:23:16 WARNING - One or more unittests failed.
[task 2019-12-05T15:23:16.462Z] 15:23:16 INFO - INFO | Todo: 0
[task 2019-12-05T15:23:16.462Z] 15:23:16 INFO - INFO | Retried: 2
[task 2019-12-05T15:23:16.463Z] 15:23:16 INFO - SUITE-END | took 300s
[task 2019-12-05T15:23:16.464Z] 15:23:16 INFO - Node moz-http2 server shutting down ...
[task 2019-12-05T15:23:16.465Z] 15:23:16 INFO - Process stdout
[task 2019-12-05T15:23:16.465Z] 15:23:16 INFO - forked process without handler sent: [object Object]
[task 2019-12-05T15:23:16.466Z] 15:23:16 INFO - Process stderr
[task 2019-12-05T15:23:16.467Z] 15:23:16 INFO - (node:1027) ExperimentalWarning: The http2 module is an experimental API.
[task 2019-12-05T15:23:16.468Z] 15:23:16 INFO - (node:1027) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2019-12-05T15:23:16.469Z] 15:23:16 INFO - (node:1027) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2019-12-05T15:23:16.469Z] 15:23:16 INFO - (node:1027) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2019-12-05T15:23:16.470Z] 15:23:16 INFO - (node:1027) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2019-12-05T15:23:16.471Z] 15:23:16 INFO - (node:17262) ExperimentalWarning: The http2 module is an experimental API.
[task 2019-12-05T15:23:16.542Z] 15:23:16 ERROR - Return code: 1
[task 2019-12-05T15:23:16.543Z] 15:23:16 INFO - TinderboxPrint: xpcshell-xpcshell<br/>678/<em class="testfail">1</em>/0
[task 2019-12-05T15:23:16.544Z] 15:23:16 WARNING - # TBPL FAILURE #
[task 2019-12-05T15:23:16.545Z] 15:23:16 WARNING - setting return code to 2
[task 2019-12-05T15:23:16.546Z] 15:23:16 WARNING - The xpcshell suite: xpcshell ran with return status: FAILURE
[task 2019-12-05T15:23:16.547Z] 15:23:16 INFO - Running post-action listener: _package_coverage_data
[task 2019-12-05T15:23:16.548Z] 15:23:16 INFO - Running post-action listener: _resource_record_post_action
[task 2019-12-05T15:23:16.548Z] 15:23:16 INFO - Running post-action listener: process_java_coverage_data
[task 2019-12-05T15:23:16.549Z] 15:23:16 INFO - [mozharness: 2019-12-05 15:23:16.542714Z] Finished run-tests step (success)
[task 2019-12-05T15:23:16.550Z] 15:23:16 INFO - Running post-run listener: _resource_record_post_run
[task 2019-12-05T15:23:16.611Z] 15:23:16 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2019-12-05T15:23:16.616Z] 15:23:16 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 61.52122186495176}, {"name": "io_write_bytes", "value": 3413012480}, {"name": "io.read_bytes", "value": 12771328}, {"name": "io_write_time", "value": 401072}, {"name": "io_read_time", "value": 552}], "extraOptions": ["e10s", "taskcluster-m5.large"], "name": "xpcshell.xpcshell.3.overall"}, {"subtests": [{"name": "time", "value": 0.025791168212890625}], "name": "xpcshell.xpcshell.3.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 8.917043924331665}, {"name": "cpu_percent", "value": 51.528571428571425}], "name": "xpcshell.xpcshell.3.install"}, {"subtests": [{"name": "time", "value": 0.01924300193786621}], "name": "xpcshell.xpcshell.3.stage-files"}, {"subtests": [{"name": "time", "value": 302.8687708377838}, {"name": "cpu_percent", "value": 61.81307947019867}], "name": "xpcshell.xpcshell.3.run-tests"}]}
[task 2019-12-05T15:23:16.616Z] 15:23:16 INFO - Total resource usage - Wall time: 311s; CPU: 62.0%; Read bytes: 12771328; Write bytes: 3413012480; Read time: 552; Write time: 401072

Mathieu, could this be caused by the changes in Bug 1559132?

Flags: needinfo?(mathieu)

Bugbug thinks this bug is a regression, but please revert this change in case of error.

Keywords: regression
Summary: Perma Release TEST-UNEXPECTED-FAIL | services/settings/test/unit/test_attachments_downloader.js | xpcshell return code: 0 when Gecko 72 merges to Release on 02-01-20 → Perma Release TEST-UNEXPECTED-FAIL | services/settings/test/unit/test_attachments_downloader.js | xpcshell return code: 0 when Gecko 72 merges to Release on 2020-01-20
Summary: Perma Release TEST-UNEXPECTED-FAIL | services/settings/test/unit/test_attachments_downloader.js | xpcshell return code: 0 when Gecko 72 merges to Release on 2020-01-20 → Perma Release TEST-UNEXPECTED-FAIL | services/settings/test/unit/test_attachments_downloader.js | xpcshell return code: 0 when Gecko 72 merges to Release on 2019-12-30
Assignee: nobody → mathieu

I don't know how to solve this :( This seems to be related to something inside TelemetryTestUtils.assertEvents().

The test is this one: https://searchfox.org/mozilla-central/rev/923eec8d2fb8078ebc7a33a9e1ce73eac01f7446/services/settings/test/unit/test_attachments_downloader.js#231-241
And it fails with parent must be in snapshot. Has []. - false == true.

I could add a flag to skip the test on release, but maybe someone more familiar with Telemetry would have some clues.. Chris, any idea?

Flags: needinfo?(mathieu) → needinfo?(chutten)

That output means no events were recorded in the parent process between when the events were last cleared and when the TelemetryTestUtils function was called.

Since this is failing only on a release simulation specifically, I thought it could be that the probe isn't collected on release, but the probe is collected on release.

Then I thought maybe it's something that's only happening because the data collection is only now reaching release, but it landed in 67.

Then I wondered if it's because the test is only now reaching release (which appears to be true) but maybe the data never made it. However, millions of uptake events have been recorded and reported in release. (( Wow! Millions! Is that an expected volume? ))

I'm afraid I don't know what mechanism by which this test would be failing all of a sudden on 72, on release only. Maybe a timing thing? (no idea)

Flags: needinfo?(chutten)

Mathieu can you debug this test locally?

Aryx can probably help if you need it, to set up a release build.

Flags: needinfo?(mathieu)

Thanks a lot Cris for the investigation. Regarding volume, the events are sampled, but this is a generic event and it's used by all components leveraging Remote Settings, as well as Normandy recipes etc.

Regarding this failure, I will skip the test in release and that's it. I am crawling under several similar tickets and have very little time. If you couldn't figure out, then I don't think I will be able to do better :/

Flags: needinfo?(mathieu)

...sampling.

That's what makes the test fail in release 🙄

Patch sent.

Pushed by mleplatre@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/2e2cf08fe827 Fix Remote Settings test about events on release r=glasserc
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 73
Status: RESOLVED → VERIFIED
Flags: needinfo?(aryx.bugmail)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: