Closed Bug 1765426 Opened 3 years ago Closed 3 years ago

Intermittent TVw-fis ::: Test verification FAIL | TinderboxPrint: Per-test run of .../contain-inline-size-replaced.html<br/>: FAILURE

Categories

(Core :: Layout, defect, P5)

Product:
Core
Component:
Layout
Type:
defect

Tracking

()

Status:
VERIFIED DUPLICATE of bug 1734020
Milestone:
101 Branch
Tracking Flags:
Tracking Status
firefox101 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Backed out changeset 85873d5c7978 (Bug 1765426)
48 bytes, text/x-phabricator-request
Details | Review

Filed by: mlaza [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=375031086&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/N0xnQHiXRAaRxb_VFmc8eA/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/N0xnQHiXRAaRxb_VFmc8eA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2022-04-19T18:44:53.035Z] 18:44:53     INFO - ::: Running tests in a loop with restarts 5 times : PASS
[task 2022-04-19T18:44:53.035Z] 18:44:53     INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=0xfb : FAIL
[task 2022-04-19T18:44:53.036Z] 18:44:53     INFO - :::
[task 2022-04-19T18:44:53.036Z] 18:44:53    ERROR - ::: Test verification FAIL
[task 2022-04-19T18:44:53.036Z] 18:44:53     INFO - :::
[task 2022-04-19T18:44:53.290Z] 18:44:53    ERROR - Return code: 1
[task 2022-04-19T18:44:53.290Z] 18:44:53    ERROR - # TBPL FAILURE #
[task 2022-04-19T18:44:53.290Z] 18:44:53  WARNING - setting return code to 2
[task 2022-04-19T18:44:53.291Z] 18:44:53    ERROR - TinderboxPrint: Per-test run of .../contain-inline-size-replaced.html<br/>: FAILURE
[task 2022-04-19T18:44:53.291Z] 18:44:53     INFO - Running post-action listener: _package_coverage_data
[task 2022-04-19T18:44:53.291Z] 18:44:53     INFO - Running post-action listener: _resource_record_post_action
[task 2022-04-19T18:44:53.291Z] 18:44:53     INFO - Running post-action listener: process_java_coverage_data
[task 2022-04-19T18:44:53.291Z] 18:44:53     INFO - Running post-action listener: stop_device
[task 2022-04-19T18:44:53.291Z] 18:44:53     INFO - [mozharness: 2022-04-19 18:44:53.291460Z] Finished run-tests step (success)
[task 2022-04-19T18:44:53.291Z] 18:44:53     INFO - Running post-run listener: _resource_record_post_run
[task 2022-04-19T18:44:53.367Z] 18:44:53     INFO - Total resource usage - Wall time: 181s; CPU: 8%; Read bytes: 149204992; Write bytes: 609288192; Read time: 1591; Write time: 1998
[task 2022-04-19T18:44:53.367Z] 18:44:53     INFO - TinderboxPrint: CPU usage<br/>7.7%
[task 2022-04-19T18:44:53.367Z] 18:44:53     INFO - TinderboxPrint: I/O read bytes / time<br/>149,204,992 / 1,591
[task 2022-04-19T18:44:53.367Z] 18:44:53     INFO - TinderboxPrint: I/O write bytes / time<br/>609,288,192 / 1,998
[task 2022-04-19T18:44:53.367Z] 18:44:53     INFO - TinderboxPrint: CPU idle<br/>2,004.5 (92.1%)
[task 2022-04-19T18:44:53.367Z] 18:44:53     INFO - TinderboxPrint: CPU system<br/>52.8 (2.4%)
[task 2022-04-19T18:44:53.367Z] 18:44:53     INFO - TinderboxPrint: CPU user<br/>118.8 (5.5%)
[task 2022-04-19T18:44:53.367Z] 18:44:53     INFO - TinderboxPrint: Swap in / out<br/>533,995,520 / 0
[task 2022-04-19T18:44:53.368Z] 18:44:53     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-04-19T18:44:53.368Z] 18:44:53     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-04-19T18:44:53.368Z] 18:44:53     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-04-19T18:44:53.368Z] 18:44:53     INFO - install - Wall time: 20s; CPU: 14%; Read bytes: 225302016; Write bytes: 222957568; Read time: 15168; Write time: 448
[task 2022-04-19T18:44:53.370Z] 18:44:53     INFO - run-tests - Wall time: 163s; CPU: 7%; Read bytes: 101961728; Write bytes: 354672640; Read time: 1029; Write time: 1332
[task 2022-04-19T18:44:53.417Z] 18:44:53  WARNING - returning nonzero exit status 2
[taskcluster 2022-04-19T18:44:53.697Z]    Exit Code: 2
[taskcluster 2022-04-19T18:44:53.697Z]    User Time: 2m18.480093s
[taskcluster 2022-04-19T18:44:53.697Z]  Kernel Time: 41.718203s
[taskcluster 2022-04-19T18:44:53.697Z]    Wall Time: 4m18.55218s
[taskcluster 2022-04-19T18:44:53.697Z]       Result: FAILED
[taskcluster 2022-04-19T18:44:53.698Z] === Task Finished ===
[taskcluster 2022-04-19T18:44:53.698Z] Task Duration: 4m18.557065s
[taskcluster 2022-04-19T18:44:53.755Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-04-19T17:49:32.263Z
[taskcluster 2022-04-19T18:44:53.960Z] 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-04-19T17:49:32.263Z
[taskcluster 2022-04-19T18:44:54.521Z] 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-04-19T17:49:32.263Z
[taskcluster 2022-04-19T18:44:54.660Z] 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-04-19T17:49:32.263Z
[taskcluster 2022-04-19T18:44:54.882Z] 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-04-19T17:49:32.263Z
[taskcluster 2022-04-19T18:44:54.982Z] 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-04-19T17:49:32.263Z
[taskcluster 2022-04-19T18:44:55.110Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/N0xnQHiXRAaRxb_VFmc8eA/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-04-19T17:49:32.263Z
[taskcluster:error] exit status 2
Regressed by: 1755565

Hm, so for repeated tests with chaos_mode_flags set, looks like the longest execution time (8190 ms) is considered "slow" (0.8 * timeout = 8000 ms) and that causes a test failure. This behaviour comes from upstream.

The reason why it may have issues on our end could be that our codebase sets chaos mode to 0xfb where upstream sets it to 0x03.

bug 1734020 mentions how slower chaos mode of 0xfb can be.

Otherwise, the tests actually pass.

Sounds like we can mark this as a dependency of bug 1734020 and not worry too much about it for now, then.

(The good news is that we only do these test-verify runs (with e.g. chaos_mode) for individual tests when they change, so this test-failure isn't going to show up often or ever; just in the rare instances when someone lands a change that modifies this test.)

Depends on: tv-chaosmode-timeout-wpt

(I'm also moving bug 1755565 to be a dependency rather than the "regressor" here. That's where this test was created, so it's not that we landed something that made this test start failing, but rather this is just a new test and it has always failed [timed out] under this particular chaos-mode configuration.)

One possible fix here, if we need or want: it looks like WPT tests can have <meta name="timeout" content="long">; I'm not sure what "long" is but maybe it's a useful way of mitigating this?

Depends on: 1755565
Keywords: regression
No longer regressed by: 1755565

Looks like "long" is 60 seconds (as opposed to the default timeout of 10 seconds):
https://searchfox.org/mozilla-central/rev/3e21f2bb69734804d311e16b914c4efcc94bb18d/testing/web-platform/tests/tools/wptrunner/wptrunner/wpttest.py#210-211

That (and really 0.8*60 = 48 seconds as a flaky-threshold) would give us plenty of breathing room, even under chaos mode where our test runs for this test are on the order of 8 seconds.

So maybe worth just adding <meta name="timeout" content="long"> to this test and calling this fixed?

Flags: needinfo?(dshin)

That makes sense - Will do. Just will need to take care to not propagate this upstream (Whatever that involves) since this is specific to our environment.

Assignee: nobody → dshin
Status: NEW → ASSIGNED
Flags: needinfo?(dshin)
Attachment #9273067 - Attachment description: Bug 1765426 - Specify long timeout to for chaos mode 0xfb runs. r=dholbert → Bug 1765426 - Use longer timeout for WPT contain-inline-size-replaced.html. r=dholbert
Pushed by dholbert@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/85873d5c7978 Use longer timeout for WPT contain-inline-size-replaced.html. r=dholbert
Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/33719 for changes under testing/web-platform/tests

https://hg.mozilla.org/mozilla-central/rev/85873d5c7978

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox101: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 101 Branch
Upstream PR merged by moz-wptsync-bot

(In reply to Pulsebot from comment #7)

Use longer timeout for WPT contain-inline-size-replaced.html. r=dholbert

In retrospect, we should not have done this. There's no reason this test needs a "long timeout"; it usually takes on the order of 100-200ms, nowhere near the 10 second threshold. If we had to mark every 100-200ms test as needing a "long timeout", that would be a lot of tests.

At the time I posted comment 4, I think I didn't realize what a broad issue bug 1734020 was. (But I am a bit more aware of it now, now that we've gotten a handful of additional bugs like this one which we've duped there.)

I'm going to back out 85873d5c7978 (comment 7) and I think we need to take some sort of action to address bug 1734020 more directly.

In the meantime, that does mean that test-verify runs for this test might "fail" again, but that's ~fine because such runs are exceedingly rare, and we essentially understand why they're failing and we know that addressing bug 1734020 is the way to stop them.

We previously annotated this test as needing a long timeout, since it can reach
the 10-second test-timeout threshold when run with "aggressive" chaos mode,
i.e. with MOZ_CHAOSMODE=0xfb. However, when run normally, the test takes
~100-200ms, so it's silly that we're considering it as needing a "long
timeout".

Really, we should address the timeout by changing the thresholds in our
test-verify/chaos-mode test harness, rather than by doing one-off "long
timeout" annotations for every test that's slow in chaos mode (which turns out
to be quite a lot of tests).

Resolution: FIXED → DUPLICATE

(The core issue here is bug 1734020 so I think we should consider this a dupe of that bug. Marking as such, for consistency & to make it easier to get an idea of the scale of the issue over there based on dupe-count.)

No longer depends on: tv-chaosmode-timeout-wpt

Following up on two points:

(In reply to Daniel Holbert [:dholbert] from comment #13)

I'm going to back out 85873d5c7978 (comment 7)

I just triggered lando to do that. This will probably trigger a test-verify job for this test, which might fail for reasons described here. That's not surprising, it'll just be more evidence that we need to address bug 1734020.

I think we need to take some sort of action to address bug 1734020 more directly.

There's now some discussion happening over there on how to do that, FWIW.

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/35952 for changes under testing/web-platform/tests
Upstream PR merged by moz-wptsync-bot

A patch has been attached on this bug, which was already closed. Filing a separate bug will ensure better tracking. If this was not by mistake and further action is needed, please alert the appropriate party. (Or: if the patch doesn't change behavior -- e.g. landing a test case, or fixing a typo -- then feel free to disregard this message)

Attachment #9273067 - Attachment is obsolete: true
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: