1762093 - Intermittent TVw-fis TinderboxPrint: Per-test run of .../multicol-span-all-010.html<br/>: FAILURE

Status: RESOLVED DUPLICATE of bug 1760979

(Testing :: web-platform-tests, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-03-30T00:30:38.297Z] 00:30:38     INFO - TEST-START | /css/css-multicol/multicol-span-all-010.html
[task 2022-03-30T00:30:38.298Z] 00:30:38     INFO - Run 9/10
[task 2022-03-30T00:30:38.300Z] 00:30:38     INFO - PID 1284 | 1648600238299	Marionette	INFO	Testing http://web-platform.test:8000/css/css-multicol/multicol-span-all-010.html == http://web-platform.test:8000/css/css-multicol/multicol-span-all-010-ref.html
[task 2022-03-30T00:30:38.449Z] 00:30:38     INFO - PID 1284 | 1648600238448	Marionette	INFO	No differences allowed
[task 2022-03-30T00:30:38.451Z] 00:30:38     INFO - TEST-PASS | /css/css-multicol/multicol-span-all-010.html | took 153ms
[task 2022-03-30T00:30:38.451Z] 00:30:38     INFO - No more tests
[task 2022-03-30T00:30:38.508Z] 00:30:38     INFO - PID 1284 | 1648600238507	Marionette	INFO	Stopped listening on port 39996
[task 2022-03-30T00:30:38.952Z] 00:30:38     INFO - Browser exited with return code 0
[task 2022-03-30T00:30:38.954Z] 00:30:38     INFO - Closing logging queue
[task 2022-03-30T00:30:38.955Z] 00:30:38     INFO - queue closed
[task 2022-03-30T00:30:38.968Z] 00:30:38     INFO - Got 0 unexpected results, with 0 unexpected passes
[task 2022-03-30T00:30:38.968Z] 00:30:38     INFO - SUITE-END | took 7s
[task 2022-03-30T00:30:39.206Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:8001
[task 2022-03-30T00:30:39.206Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:8003
[task 2022-03-30T00:30:39.206Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:8445
[task 2022-03-30T00:30:39.206Z] 00:30:39     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
[task 2022-03-30T00:30:39.206Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:8002
[task 2022-03-30T00:30:39.206Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:8443
[task 2022-03-30T00:30:39.206Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:8444
[task 2022-03-30T00:30:39.206Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:9000
[task 2022-03-30T00:30:39.207Z] 00:30:39     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
[task 2022-03-30T00:30:39.207Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:8446
[task 2022-03-30T00:30:39.382Z] 00:30:39     INFO - wptserve Stopped http server on 127.0.0.1:8000
[task 2022-03-30T00:30:39.430Z] 00:30:39     INFO - Removed font: Ahem.ttf
[task 2022-03-30T00:30:39.489Z] 00:30:39     INFO - Closing logging queue
[task 2022-03-30T00:30:39.489Z] 00:30:39     INFO - queue closed
[task 2022-03-30T00:30:39.523Z] 00:30:39     INFO - ::: Ran 1 of expected 10 iterations.
[task 2022-03-30T00:30:39.524Z] 00:30:39     INFO - ::: Reached iteration timeout before finishing 2 or more repeat runs.
[task 2022-03-30T00:30:39.524Z] 00:30:39     INFO - ::: At least 2 successful repeat runs are required to validate stability.
[task 2022-03-30T00:30:39.525Z] 00:30:39     INFO - ::: Running tests in a loop 10 times : FAIL
[task 2022-03-30T00:30:39.525Z] 00:30:39     INFO - :::
[task 2022-03-30T00:30:39.526Z] 00:30:39  WARNING - ::: Test verification TIMEOUT
[task 2022-03-30T00:30:39.526Z] 00:30:39     INFO - :::
[task 2022-03-30T00:30:39.787Z] 00:30:39    ERROR - Return code: 1
[task 2022-03-30T00:30:39.788Z] 00:30:39    ERROR - # TBPL FAILURE #
[task 2022-03-30T00:30:39.788Z] 00:30:39  WARNING - setting return code to 2
[task 2022-03-30T00:30:39.788Z] 00:30:39    ERROR - TinderboxPrint: Per-test run of .../multicol-span-all-010.html<br/>: FAILURE
[task 2022-03-30T00:30:39.789Z] 00:30:39     INFO - Running post-action listener: _package_coverage_data
[task 2022-03-30T00:30:39.789Z] 00:30:39     INFO - Running post-action listener: _resource_record_post_action
[task 2022-03-30T00:30:39.789Z] 00:30:39     INFO - Running post-action listener: process_java_coverage_data
[task 2022-03-30T00:30:39.789Z] 00:30:39     INFO - Running post-action listener: stop_device
[task 2022-03-30T00:30:39.789Z] 00:30:39     INFO - [mozharness: 2022-03-30 00:30:39.789400Z] Finished run-tests step (success)
[task 2022-03-30T00:30:39.789Z] 00:30:39     INFO - Running post-run listener: _resource_record_post_run
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - Total resource usage - Wall time: 31s; CPU: 28%; Read bytes: 0; Write bytes: 178696192; Read time: 0; Write time: 6552
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - TinderboxPrint: CPU usage<br/>28.3%
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - TinderboxPrint: I/O read bytes / time<br/>0 / 0
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - TinderboxPrint: I/O write bytes / time<br/>178,696,192 / 6,552
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - TinderboxPrint: CPU idle<br/>88.6 (71.6%)
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - TinderboxPrint: CPU system<br/>3.9 (3.1%)
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - TinderboxPrint: CPU user<br/>31.1 (25.1%)
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2022-03-30T00:30:39.842Z] 00:30:39     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-03-30T00:30:39.842Z] 00:30:39     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-03-30T00:30:39.842Z] 00:30:39     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-03-30T00:30:39.843Z] 00:30:39     INFO - install - Wall time: 12s; CPU: 25%; Read bytes: 0; Write bytes: 8192; Read time: 0; Write time: 0
[task 2022-03-30T00:30:39.843Z] 00:30:39     INFO - run-tests - Wall time: 20s; CPU: 30%; Read bytes: 0; Write bytes: 178688000; Read time: 0; Write time: 6552
[task 2022-03-30T00:30:39.849Z] 00:30:39  WARNING - returning nonzero exit status 2

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 3

[David Shin[:dshin]]

(Not too familiar with test infra, let me know if there is any misunderstanding)
Reproducible with ./mach web-platform-tests --verify --include ./testing/web-platform/tests/css/css-multicol/multicol-span-all-010.html
Looks like in the trace, the test did run 10 times in a loop but the harness doesn't think so.
Tracked it down to a changeset introduced by Bug 1750469 - looks like we've started returning a wrong # iterations around here
Reverting the changeset in question allows the test to run to completion with a PASS locally.

:jgraham, looks like the changeset was meant to be a refactor - do you think reverting is the best way to go?

Comment 4

[James Graham [:jgraham]]

I landed a fix for this; see 1760979