Closed Bug 1780838 Opened 3 years ago Closed 2 years ago

Intermittent TVw TinderboxPrint: Per-test run of .../contain-intrinsic-size-028.html<br/>: FAILURE

Categories

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

defect

Tracking

(firefox-esr91 unaffected, firefox-esr102 unaffected, firefox103 unaffected, firefox104 wontfix, firefox105 wontfix)

RESOLVED DUPLICATE of bug 1734020
Tracking Status
firefox-esr91 --- unaffected
firefox-esr102 --- unaffected
firefox103 --- unaffected
firefox104 --- wontfix
firefox105 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

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


[task 2022-07-22T15:32:25.666Z] 15:32:25     INFO - TEST-START | /css/css-sizing/contain-intrinsic-size/contain-intrinsic-size-028.html
[task 2022-07-22T15:32:25.666Z] 15:32:25     INFO - Run 9/10
[task 2022-07-22T15:32:25.760Z] 15:32:25     INFO - Closing window d8389aef-bd1a-4d6d-84f3-d7cae344aac5
[task 2022-07-22T15:32:28.887Z] 15:32:28     INFO - ........................
[task 2022-07-22T15:32:28.887Z] 15:32:28     INFO - TEST-OK | /css/css-sizing/contain-intrinsic-size/contain-intrinsic-size-028.html | took 3220ms
[task 2022-07-22T15:32:28.887Z] 15:32:28     INFO - No more tests
[task 2022-07-22T15:32:28.888Z] 15:32:28     INFO - PID 1772 | 1658503948885	Marionette	INFO	Stopped listening on port 49453
[task 2022-07-22T15:32:31.473Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=15b29b800 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3587
[task 2022-07-22T15:32:31.474Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=15b29b800 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1791
[task 2022-07-22T15:32:31.475Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=134dd5000 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3587
[task 2022-07-22T15:32:31.475Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=134dd5000 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1791
[task 2022-07-22T15:32:31.476Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=15925e800 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3587
[task 2022-07-22T15:32:31.476Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=15925e800 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1791
[task 2022-07-22T15:32:31.630Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=15b29b800 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1826
[task 2022-07-22T15:32:31.630Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=15b29b800 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3689
[task 2022-07-22T15:32:31.675Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=134dd5000 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1826
[task 2022-07-22T15:32:31.676Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=134dd5000 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3689
[task 2022-07-22T15:32:31.725Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=15925e800 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1826
[task 2022-07-22T15:32:31.726Z] 15:32:31     INFO - PID 1772 | [Parent 1772, Main Thread] WARNING: ContentParent: id=15925e800 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3689
[task 2022-07-22T15:32:34.373Z] 15:32:34     INFO - Browser exited with return code 0
[task 2022-07-22T15:32:34.376Z] 15:32:34     INFO - Closing logging queue
[task 2022-07-22T15:32:34.376Z] 15:32:34     INFO - queue closed
[task 2022-07-22T15:32:34.398Z] 15:32:34     INFO - Got 0 unexpected results, with 0 unexpected passes
[task 2022-07-22T15:32:34.399Z] 15:32:34     INFO - SUITE-END | took 96s
[task 2022-07-22T15:32:34.474Z] 15:32:34     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
[task 2022-07-22T15:32:34.612Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:8000
[task 2022-07-22T15:32:34.612Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:8445
[task 2022-07-22T15:32:34.613Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:8446
[task 2022-07-22T15:32:34.613Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:8443
[task 2022-07-22T15:32:34.696Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:8444
[task 2022-07-22T15:32:34.801Z] 15:32:34     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
[task 2022-07-22T15:32:34.823Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:8002
[task 2022-07-22T15:32:34.823Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:9000
[task 2022-07-22T15:32:34.905Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:8003
[task 2022-07-22T15:32:34.906Z] 15:32:34     INFO - wptserve Stopped http server on 127.0.0.1:8001
[task 2022-07-22T15:32:34.983Z] 15:32:34     INFO - Closing logging queue
[task 2022-07-22T15:32:34.984Z] 15:32:34     INFO - queue closed
[task 2022-07-22T15:32:35.013Z] 15:32:35     INFO - ::: Ran 10 of expected 10 iterations.
[task 2022-07-22T15:32:35.013Z] 15:32:35     INFO - ## All results ##
[task 2022-07-22T15:32:35.013Z] 15:32:35     INFO - 
[task 2022-07-22T15:32:35.014Z] 15:32:35     INFO - ### /css/css-sizing/contain-intrinsic-size/contain-intrinsic-size-028.html ###
[task 2022-07-22T15:32:35.014Z] 15:32:35     INFO - |  Subtest   | Results |                                                                                             Messages                                                                                             |
[task 2022-07-22T15:32:35.015Z] 15:32:35     INFO - |------------|---------|--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
[task 2022-07-22T15:32:35.015Z] 15:32:35     INFO - |            | OK      |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.016Z] 15:32:35     INFO - | `.test 1`  | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.016Z] 15:32:35     INFO - | `.test 2`  | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.017Z] 15:32:35     INFO - | `.test 3`  | FAIL    | `assert_equals: \n<div class="test cis-width" data-expected-client-width="100" data-expected-client-height="20"></div>\nclientWidth expected 100 but got 0`                                      |
[task 2022-07-22T15:32:35.018Z] 15:32:35     INFO - | `.test 4`  | FAIL    | `assert_equals: \n<div class="test cis-both" data-expected-client-width="100" data-expected-client-height="20"></div>\nclientWidth expected 100 but got 0`                                       |
[task 2022-07-22T15:32:35.018Z] 15:32:35     INFO - | `.test 5`  | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.019Z] 15:32:35     INFO - | `.test 6`  | FAIL    | `assert_equals: \n<div class="test cis-height vertical" data-expected-client-width="40" data-expected-client-height="50"></div>\nclientHeight expected 50 but got 0`                             |
[task 2022-07-22T15:32:35.019Z] 15:32:35     INFO - | `.test 7`  | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.020Z] 15:32:35     INFO - | `.test 8`  | FAIL    | `assert_equals: \n<div class="test cis-both vertical" data-expected-client-width="40" data-expected-client-height="50"></div>\nclientHeight expected 50 but got 0`                               |
[task 2022-07-22T15:32:35.020Z] 15:32:35     INFO - | `.test 9`  | FAIL    | `assert_equals: \n<img class="test cis-none" src="/css/support/60x60-green.png" data-expected-client-width="60" data-expected-client-height="60">\nclientWidth expected 60 but got 0`            |
[task 2022-07-22T15:32:35.021Z] 15:32:35     INFO - | `.test 10` | FAIL    | `assert_equals: \n<img class="test cis-height" src="/css/support/60x60-green.png" data-expected-client-width="60" data-expected-client-height="60">\nclientWidth expected 60 but got 0`          |
[task 2022-07-22T15:32:35.021Z] 15:32:35     INFO - | `.test 11` | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.021Z] 15:32:35     INFO - | `.test 12` | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.022Z] 15:32:35     INFO - | `.test 13` | FAIL    | `assert_equals: \n<img class="test cis-none vertical" src="/css/support/60x60-green.png" data-expected-client-width="60" data-expected-client-height="60">\nclientHeight expected 60 but got 0`  |
[task 2022-07-22T15:32:35.022Z] 15:32:35     INFO - | `.test 14` | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.023Z] 15:32:35     INFO - | `.test 15` | FAIL    | `assert_equals: \n<img class="test cis-width vertical" src="/css/support/60x60-green.png" data-expected-client-width="60" data-expected-client-height="60">\nclientHeight expected 60 but got 0` |
[task 2022-07-22T15:32:35.023Z] 15:32:35     INFO - | `.test 16` | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.024Z] 15:32:35     INFO - | `.test 17` | FAIL    | `assert_equals: \n<svg class="test cis-none" data-expected-client-width="300" data-expected-client-height="150"></svg>\nclientWidth expected 300 but got 0`                                      |
[task 2022-07-22T15:32:35.024Z] 15:32:35     INFO - | `.test 18` | FAIL    | `assert_equals: \n<svg class="test cis-height" data-expected-client-width="300" data-expected-client-height="150"></svg>\nclientWidth expected 300 but got 0`                                    |
[task 2022-07-22T15:32:35.025Z] 15:32:35     INFO - | `.test 19` | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.025Z] 15:32:35     INFO - | `.test 20` | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.026Z] 15:32:35     INFO - | `.test 21` | FAIL    | `assert_equals: \n<svg class="test cis-none vertical" data-expected-client-width="300" data-expected-client-height="150"></svg>\nclientHeight expected 150 but got 0`                            |
[task 2022-07-22T15:32:35.026Z] 15:32:35     INFO - | `.test 22` | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.027Z] 15:32:35     INFO - | `.test 23` | FAIL    | `assert_equals: \n<svg class="test cis-width vertical" data-expected-client-width="300" data-expected-client-height="150"></svg>\nclientHeight expected 150 but got 0`                           |
[task 2022-07-22T15:32:35.027Z] 15:32:35     INFO - | `.test 24` | PASS    |                                                                                                                                                                                                  |
[task 2022-07-22T15:32:35.028Z] 15:32:35     INFO - 
[task 2022-07-22T15:32:35.028Z] 15:32:35     INFO - ## Slow tests ##
[task 2022-07-22T15:32:35.028Z] 15:32:35     INFO - 
[task 2022-07-22T15:32:35.028Z] 15:32:35     INFO - |                                   Test                                   | Result | Longest duration (ms) | Timeout (ms) |
[task 2022-07-22T15:32:35.029Z] 15:32:35     INFO - |--------------------------------------------------------------------------|--------|-----------------------|--------------|
[task 2022-07-22T15:32:35.029Z] 15:32:35     INFO - | `/css/css-sizing/contain-intrinsic-size/contain-intrinsic-size-028.html` | `OK`   | `8922`                | `10000`      |
[task 2022-07-22T15:32:35.029Z] 15:32:35     INFO - 
[task 2022-07-22T15:32:35.030Z] 15:32:35     INFO - ::: Running tests in a loop 10 times : PASS
[task 2022-07-22T15:32:35.030Z] 15:32:35     INFO - ::: Running tests in a loop with restarts 5 times : PASS
[task 2022-07-22T15:32:35.030Z] 15:32:35     INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=0xfb : FAIL
[task 2022-07-22T15:32:35.031Z] 15:32:35     INFO - :::
[task 2022-07-22T15:32:35.031Z] 15:32:35    ERROR - ::: Test verification FAIL
[task 2022-07-22T15:32:35.031Z] 15:32:35     INFO - :::
[task 2022-07-22T15:32:35.355Z] 15:32:35    ERROR - Return code: 1
[task 2022-07-22T15:32:35.356Z] 15:32:35    ERROR - # TBPL FAILURE #
[task 2022-07-22T15:32:35.356Z] 15:32:35  WARNING - setting return code to 2
[task 2022-07-22T15:32:35.356Z] 15:32:35    ERROR - TinderboxPrint: Per-test run of .../contain-intrinsic-size-028.html<br/>: FAILURE
[task 2022-07-22T15:32:35.356Z] 15:32:35     INFO - Running post-action listener: _package_coverage_data
[task 2022-07-22T15:32:35.356Z] 15:32:35     INFO - Running post-action listener: _resource_record_post_action
[task 2022-07-22T15:32:35.356Z] 15:32:35     INFO - Running post-action listener: process_java_coverage_data
[task 2022-07-22T15:32:35.356Z] 15:32:35     INFO - Running post-action listener: stop_device
[task 2022-07-22T15:32:35.356Z] 15:32:35     INFO - [mozharness: 2022-07-22 15:32:35.356789Z] Finished run-tests step (success)
[task 2022-07-22T15:32:35.356Z] 15:32:35     INFO - Running post-run listener: _resource_record_post_run
[task 2022-07-22T15:32:35.430Z] 15:32:35     INFO - Total resource usage - Wall time: 182s; CPU: 8%; Read bytes: 106254336; Write bytes: 639209472; Read time: 2033; Write time: 1887
[task 2022-07-22T15:32:35.430Z] 15:32:35     INFO - TinderboxPrint: CPU usage<br/>8.2%
[task 2022-07-22T15:32:35.430Z] 15:32:35     INFO - TinderboxPrint: I/O read bytes / time<br/>106,254,336 / 2,033
[task 2022-07-22T15:32:35.430Z] 15:32:35     INFO - TinderboxPrint: I/O write bytes / time<br/>639,209,472 / 1,887
[task 2022-07-22T15:32:35.430Z] 15:32:35     INFO - TinderboxPrint: CPU idle<br/>2,005.1 (91.8%)
[task 2022-07-22T15:32:35.431Z] 15:32:35     INFO - TinderboxPrint: CPU system<br/>49.0 (2.2%)
[task 2022-07-22T15:32:35.431Z] 15:32:35     INFO - TinderboxPrint: CPU user<br/>129.5 (5.9%)
[task 2022-07-22T15:32:35.431Z] 15:32:35     INFO - TinderboxPrint: Swap in / out<br/>333,185,024 / 0
[task 2022-07-22T15:32:35.431Z] 15:32:35     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-22T15:32:35.431Z] 15:32:35     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-22T15:32:35.431Z] 15:32:35     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-22T15:32:35.432Z] 15:32:35     INFO - install - Wall time: 19s; CPU: 14%; Read bytes: 252880384; Write bytes: 244686848; Read time: 16363; Write time: 335
[task 2022-07-22T15:32:35.434Z] 15:32:35     INFO - run-tests - Wall time: 163s; CPU: 8%; Read bytes: 90595328; Write bytes: 376516608; Read time: 1443; Write time: 1525
[task 2022-07-22T15:32:35.478Z] 15:32:35  WARNING - returning nonzero exit status 2
[taskcluster 2022-07-22T15:32:35.755Z]    Exit Code: 2
[taskcluster 2022-07-22T15:32:35.755Z]    User Time: 2m26.966248s
[taskcluster 2022-07-22T15:32:35.755Z]  Kernel Time: 41.601297s
[taskcluster 2022-07-22T15:32:35.755Z]    Wall Time: 4m17.443364s
[taskcluster 2022-07-22T15:32:35.755Z]       Result: FAILED
[taskcluster 2022-07-22T15:32:35.755Z] === Task Finished ===
[taskcluster 2022-07-22T15:32:35.756Z] Task Duration: 4m17.446946s
[taskcluster 2022-07-22T15:32:35.855Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-22T15:03:21.339Z
[taskcluster 2022-07-22T15:32:36.115Z] 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-22T15:03:21.339Z
[taskcluster 2022-07-22T15:32:36.644Z] 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-22T15:03:21.339Z
[taskcluster 2022-07-22T15:32:36.759Z] 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-22T15:03:21.339Z
[taskcluster 2022-07-22T15:32:37.076Z] 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-22T15:03:21.339Z
[taskcluster 2022-07-22T15:32:37.168Z] 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-22T15:03:21.339Z
[taskcluster 2022-07-22T15:32:37.310Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/V3MzCmPjQxK0tlVxclezpw/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-07-22T15:03:21.339Z
[taskcluster:error] exit status 2
Regressed by: 1780475

Emilio can you take a look at this?
thank you.

Flags: needinfo?(emilio)

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

I couldn't reproduce locally with ./mach wpt --verify testing/web-platform/tests/css/css-sizing/contain-intrinsic-size/contain-intrinsic-size-028.html after a couple tries. Maybe the pref wasn't correctly set on that run or something? Otherwise I don't see how it can fail so catastrophically.

I'm almost sure after double-checking the test that the test is sound, this seems an issue with verify mode.

My best hypothesis is that chaos mode made the pref changes not getting synced on time to the content process, which didn't enable the feature this test was testing... James, does that sound plausible? In any case I don't think this is worth worrying about too much.

Flags: needinfo?(emilio) → needinfo?(james)

I also can't reproduce, but I'm not on mac. I notice a slow test warning in the logs, so it's also possible that there's a timing issue there (or maybe the slow test warning doesn't account for the repeats, I"m not sure). In any case I agree this isn't worth spending time on unless we see the test start to fail in a non-verify configuration.

Flags: needinfo?(james)

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

Flags: needinfo?(oriol-bugzilla)

Per the comments above I think it's better to wait a bit in case it was just a punctual thing unrelated to the test.

Flags: needinfo?(oriol-bugzilla)

(In reply to James Graham [:jgraham] from comment #5)

I notice a slow test warning in the logs

This slow-test-warning (which gets treated as a test-verify failure) is tracked as bug 1734020.

It looks like originally there were other test-failures here as well, besides that slow-test issue -- comment 0 showed a bunch of FAIL results for various subtests -- but those were all expected-failures. (Comment 0 was on July 22, and at that point our expectations for this test were
https://hg.mozilla.org/integration/autoland/annotate/2120ff6ddc2245eac63351cdf7053d685dfc1194/testing/web-platform/meta/css/css-sizing/contain-intrinsic-size/contain-intrinsic-size-028.html.ini
which are exactly the failures quoted in comment 0 -- subtests 3,4,6,8,9,10,13,15,17,18,21,23.

So I think the only issue here was the "slow test" category of failure, so let's dupe to bug 1734020.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.