Closed Bug 1782079 Opened 2 years ago Closed 2 years ago

Intermittent TVw ::: Test verification FAIL | TinderboxPrint: Per-test run of .../blob-composite-blob-reads.any.js<br/>: FAILURE

Categories

(Core :: Storage: IndexedDB, defect, P5)

Product:
Core
Component:
Storage: IndexedDB
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
105 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox-esr102 --- unaffected
firefox103 --- unaffected
firefox104 --- unaffected
firefox105 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Bug 1782079 - Mark new test as "long" timeout and reduce runtime. r=nika!
48 bytes, text/x-phabricator-request
Details | Review

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=385686384&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/HFjEwLouT9WYYrs8g4BcoA/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/HFjEwLouT9WYYrs8g4BcoA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2022-07-28T15:38:38.199Z] 15:38:38     INFO - ::: Running tests in a loop 10 times : PASS
[task 2022-07-28T15:38:38.199Z] 15:38:38     INFO - ::: Running tests in a loop with restarts 5 times : PASS
[task 2022-07-28T15:38:38.200Z] 15:38:38     INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=0xfb : FAIL
[task 2022-07-28T15:38:38.200Z] 15:38:38     INFO - :::
[task 2022-07-28T15:38:38.200Z] 15:38:38    ERROR - ::: Test verification FAIL
[task 2022-07-28T15:38:38.200Z] 15:38:38     INFO - :::
[task 2022-07-28T15:38:38.541Z] 15:38:38    ERROR - Return code: 1
[task 2022-07-28T15:38:38.542Z] 15:38:38    ERROR - # TBPL FAILURE #
[task 2022-07-28T15:38:38.542Z] 15:38:38  WARNING - setting return code to 2
[task 2022-07-28T15:38:38.542Z] 15:38:38    ERROR - TinderboxPrint: Per-test run of .../blob-composite-blob-reads.any.js<br/>: FAILURE
[task 2022-07-28T15:38:38.542Z] 15:38:38     INFO - Running post-action listener: _package_coverage_data
[task 2022-07-28T15:38:38.542Z] 15:38:38     INFO - Running post-action listener: _resource_record_post_action
[task 2022-07-28T15:38:38.542Z] 15:38:38     INFO - Running post-action listener: process_java_coverage_data
[task 2022-07-28T15:38:38.542Z] 15:38:38     INFO - Running post-action listener: stop_device
[task 2022-07-28T15:38:38.542Z] 15:38:38     INFO - [mozharness: 2022-07-28 15:38:38.542916Z] Finished run-tests step (success)
[task 2022-07-28T15:38:38.543Z] 15:38:38     INFO - Running post-run listener: _resource_record_post_run
[task 2022-07-28T15:38:38.628Z] 15:38:38     INFO - Total resource usage - Wall time: 293s; CPU: 6%; Read bytes: 110448640; Write bytes: 1278324736; Read time: 1231; Write time: 3104
[task 2022-07-28T15:38:38.628Z] 15:38:38     INFO - TinderboxPrint: CPU usage<br/>5.9%
[task 2022-07-28T15:38:38.628Z] 15:38:38     INFO - TinderboxPrint: I/O read bytes / time<br/>110,448,640 / 1,231
[task 2022-07-28T15:38:38.628Z] 15:38:38     INFO - TinderboxPrint: I/O write bytes / time<br/>1,278,324,736 / 3,104
[task 2022-07-28T15:38:38.628Z] 15:38:38     INFO - TinderboxPrint: CPU idle<br/>3,297.3 (93.9%)
[task 2022-07-28T15:38:38.628Z] 15:38:38     INFO - TinderboxPrint: CPU system<br/>77.1 (2.2%)
[task 2022-07-28T15:38:38.628Z] 15:38:38     INFO - TinderboxPrint: CPU user<br/>137.5 (3.9%)
[task 2022-07-28T15:38:38.628Z] 15:38:38     INFO - TinderboxPrint: Swap in / out<br/>353,005,568 / 0
[task 2022-07-28T15:38:38.629Z] 15:38:38     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-07-28T15:38:38.629Z] 15:38:38     INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-07-28T15:38:38.629Z] 15:38:38     INFO - verify-device - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-07-28T15:38:38.630Z] 15:38:38     INFO - install - Wall time: 19s; CPU: 14%; Read bytes: 238110208; Write bytes: 226484224; Read time: 15524; Write time: 455
[task 2022-07-28T15:38:38.633Z] 15:38:38     INFO - run-tests - Wall time: 275s; CPU: 5%; Read bytes: 103063552; Write bytes: 1017380864; Read time: 1150; Write time: 2545
[task 2022-07-28T15:38:38.699Z] 15:38:38  WARNING - returning nonzero exit status 2
[taskcluster 2022-07-28T15:38:38.979Z]    Exit Code: 2
[taskcluster 2022-07-28T15:38:38.979Z]    User Time: 2m36.987324s
[taskcluster 2022-07-28T15:38:38.979Z]  Kernel Time: 52.823864s
[taskcluster 2022-07-28T15:38:38.979Z]    Wall Time: 6m8.254877s
[taskcluster 2022-07-28T15:38:38.979Z]       Result: FAILED
[taskcluster 2022-07-28T15:38:38.980Z] === Task Finished ===
[taskcluster 2022-07-28T15:38:38.980Z] Task Duration: 6m8.258373s
[taskcluster 2022-07-28T15:38:39.089Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-28T15:06:54.697Z
[taskcluster 2022-07-28T15:38:39.309Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-28T15:06:54.697Z
[taskcluster 2022-07-28T15:38:39.916Z] Uploading artifact public/test_info/wpt-test1_errorsummary.log from file build/blobber_upload_dir/wpt-test1_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2023-07-28T15:06:54.697Z
[taskcluster 2022-07-28T15:38:40.013Z] Uploading artifact public/test_info/wpt-test1_raw.log from file build/blobber_upload_dir/wpt-test1_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2023-07-28T15:06:54.697Z
[taskcluster 2022-07-28T15:38:40.210Z] Uploading artifact public/test_info/wpt_instruments.txt from file build/blobber_upload_dir/wpt_instruments.txt with content encoding "gzip", mime type "text/plain; charset=utf-8" and expiry 2023-07-28T15:06:54.697Z
[taskcluster 2022-07-28T15:38:40.301Z] Uploading artifact public/test_info/wptreport.json from file build/blobber_upload_dir/wptreport.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-28T15:06:54.697Z
[taskcluster 2022-07-28T15:38:40.432Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/HFjEwLouT9WYYrs8g4BcoA/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-07-28T15:06:54.697Z
[taskcluster:error] exit status 2

:nika, since you are the author of the regressor, bug 1780054, could you take a look?
For more information, please visit auto_nag documentation.

Flags: needinfo?(nika)

Set release status flags based on info from the regressing bug 1780054

status-firefox103: --- → unaffected
status-firefox104: --- → unaffected
status-firefox105: --- → affected
status-firefox-esr102: --- → unaffected
status-firefox-esr91: --- → unaffected

I don't entirely understand what is failing here. From looking at the logs everything appears to be reporting that it is successful until the very end when the test reports a failure. Did the test time out or something like that? It definitely looks like the verify run took a while, and I don't think it fully finished?

(turns out yes, it appears that the wptrunner's test-verify pass will error out if the test is "slow", but didn't otherwise fail: https://searchfox.org/mozilla-central/rev/4a15041348e08fb0d6f5726015c32861e663fbfe/testing/web-platform/tests/tools/wptrunner/wptrunner/stability.py#401-407, which is what I think is happening here. This isn't exactly well communicated.)

The test was written by :asuth so bringing them in to this bug as well.

Flags: needinfo?(nika) → needinfo?(bugmail)

So the secret slow/flaky threshold is 80% of the timeout which was 10 seconds in this case: https://searchfox.org/mozilla-central/rev/4a15041348e08fb0d6f5726015c32861e663fbfe/testing/web-platform/tests/tools/wptrunner/wptrunner/stability.py#23-25

# If a test takes more than (FLAKY_THRESHOLD*timeout) and does not consistently
# time out, it is considered slow (potentially flaky).
FLAKY_THRESHOLD = 0.8

And this specific failure was just over that 8 second threshold (but under the 10 second threshold):

[task 2022-07-28T15:38:38.198Z] 15:38:38     INFO - ## Slow tests ##
[task 2022-07-28T15:38:38.198Z] 15:38:38     INFO - 
[task 2022-07-28T15:38:38.198Z] 15:38:38     INFO - |                          Test                          | Result | Longest duration (ms) | Timeout (ms) |
[task 2022-07-28T15:38:38.198Z] 15:38:38     INFO - |--------------------------------------------------------|--------|-----------------------|--------------|
[task 2022-07-28T15:38:38.199Z] 15:38:38     INFO - | `/IndexedDB/blob-composite-blob-reads.any.worker.html` | `OK`   | `8520`                | `10000`      |

So I've restored the // META: timeout=long to the test that I'd removed and have disabled some potentially redundant coverage in the test. Updated test going up for review in a sec.

Assignee: nobody → bugmail
Status: NEW → ASSIGNED
Flags: needinfo?(bugmail)
Pushed by bugmail@asutherland.org: https://hg.mozilla.org/integration/autoland/rev/f6235856e5e6 Mark new test as "long" timeout and reduce runtime. r=nika
Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/35284 for changes under testing/web-platform/tests

https://hg.mozilla.org/mozilla-central/rev/f6235856e5e6

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
status-firefox105: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → 105 Branch
Upstream PR merged by moz-wptsync-bot
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: