Closed Bug 1791066 Opened 2 years ago Closed 2 years ago

Intermittent TVw ::: Test verification FAIL | TinderboxPrint: Per-test run of .../content-visibility-047.html<br/>: FAILURE

Categories

(Core :: Layout, defect, P5)

defect

Tracking

()

RESOLVED DUPLICATE of bug 1734020

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

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


[task 2022-09-15T18:12:50.943Z] 18:12:50     INFO - TEST-START | /css/css-contain/content-visibility/content-visibility-047.html
[task 2022-09-15T18:12:51.086Z] 18:12:51     INFO - Setting pref dom.animations-api.compositing.enabled to true
[task 2022-09-15T18:12:51.444Z] 18:12:51     INFO - Setting pref layout.css.cascade-layers.enabled to true
[task 2022-09-15T18:12:51.760Z] 18:12:51     INFO - Setting pref layout.css.content-visibility.enabled to true
[task 2022-09-15T18:12:56.861Z] 18:12:56     INFO - .
[task 2022-09-15T18:12:56.861Z] 18:12:56     INFO - TEST-OK | /css/css-contain/content-visibility/content-visibility-047.html | took 5918ms
[task 2022-09-15T18:12:56.862Z] 18:12:56     INFO - No more tests
[task 2022-09-15T18:12:56.878Z] 18:12:56     INFO - PID 1694 | 1663265576877	Marionette	INFO	Stopped listening on port 49732
[task 2022-09-15T18:12:56.915Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=152729d00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3635
[task 2022-09-15T18:12:56.915Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=152729d00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3641
[task 2022-09-15T18:12:56.916Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=12c4bef00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3635
[task 2022-09-15T18:12:56.916Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=12c4bef00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3641
[task 2022-09-15T18:12:56.917Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=152a76e00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3635
[task 2022-09-15T18:12:56.918Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=152a76e00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3641
[task 2022-09-15T18:12:56.919Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=15385fd00 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3635
[task 2022-09-15T18:12:56.919Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=15385fd00 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3641
[task 2022-09-15T18:12:56.920Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=153cca900 - BlockShutdown: NotifyImpendingShutdown.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3635
[task 2022-09-15T18:12:56.921Z] 18:12:56     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=153cca900 - BlockShutdown: RequestContentJSInterrupt.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3641
[task 2022-09-15T18:12:59.764Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=152a76e00 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3680
[task 2022-09-15T18:12:59.765Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=152a76e00 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1803
[task 2022-09-15T18:12:59.766Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=15385fd00 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3680
[task 2022-09-15T18:12:59.766Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=15385fd00 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1803
[task 2022-09-15T18:12:59.767Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=153cca900 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3680
[task 2022-09-15T18:12:59.768Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=153cca900 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1803
[task 2022-09-15T18:12:59.941Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=152a76e00 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1843
[task 2022-09-15T18:12:59.941Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=152a76e00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3795
[task 2022-09-15T18:12:59.982Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=15385fd00 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1843
[task 2022-09-15T18:12:59.983Z] 18:12:59     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=15385fd00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3795
[task 2022-09-15T18:13:00.041Z] 18:13:00     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=153cca900 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1843
[task 2022-09-15T18:13:00.042Z] 18:13:00     INFO - PID 1694 | [Parent 1694, Main Thread] WARNING: ContentParent: id=153cca900 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3795
[task 2022-09-15T18:13:02.822Z] 18:13:02     INFO - Browser exited with return code 0
[task 2022-09-15T18:13:02.825Z] 18:13:02     INFO - Closing logging queue
[task 2022-09-15T18:13:02.826Z] 18:13:02     INFO - queue closed
[task 2022-09-15T18:13:02.840Z] 18:13:02     INFO - Got 0 unexpected results, with 0 unexpected passes
[task 2022-09-15T18:13:02.840Z] 18:13:02     INFO - SUITE-END | took 65s
[task 2022-09-15T18:13:02.892Z] 18:13:02     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
[task 2022-09-15T18:13:02.892Z] 18:13:02     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
[task 2022-09-15T18:13:02.893Z] 18:13:02     INFO - wptserve Stopped http server on 127.0.0.1:8003
[task 2022-09-15T18:13:02.893Z] 18:13:02     INFO - wptserve Stopped http server on 127.0.0.1:9000
[task 2022-09-15T18:13:02.906Z] 18:13:02     INFO - wptserve Stopped http server on 127.0.0.1:8002
[task 2022-09-15T18:13:02.961Z] 18:13:02     INFO - wptserve Stopped http server on 127.0.0.1:8000
[task 2022-09-15T18:13:03.057Z] 18:13:03     INFO - wptserve Stopped http server on 127.0.0.1:8001
[task 2022-09-15T18:13:03.057Z] 18:13:03     INFO - wptserve Stopped http server on 127.0.0.1:8446
[task 2022-09-15T18:13:03.058Z] 18:13:03     INFO - wptserve Stopped http server on 127.0.0.1:8443
[task 2022-09-15T18:13:03.205Z] 18:13:03     INFO - wptserve Stopped http server on 127.0.0.1:8444
[task 2022-09-15T18:13:03.257Z] 18:13:03     INFO - wptserve Stopped http server on 127.0.0.1:8445
[task 2022-09-15T18:13:03.287Z] 18:13:03     INFO - Removed font: Ahem.ttf
[task 2022-09-15T18:13:03.332Z] 18:13:03     INFO - Closing logging queue
[task 2022-09-15T18:13:03.332Z] 18:13:03     INFO - queue closed
[task 2022-09-15T18:13:03.360Z] 18:13:03     INFO - ::: Ran 5 of expected 5 iterations.
[task 2022-09-15T18:13:03.361Z] 18:13:03     INFO - ## All results ##
[task 2022-09-15T18:13:03.361Z] 18:13:03     INFO - 
[task 2022-09-15T18:13:03.361Z] 18:13:03     INFO - ### /css/css-contain/content-visibility/content-visibility-047.html ###
[task 2022-09-15T18:13:03.361Z] 18:13:03     INFO - |                   Subtest                    | Results | Messages |
[task 2022-09-15T18:13:03.362Z] 18:13:03     INFO - |----------------------------------------------|---------|----------|
[task 2022-09-15T18:13:03.362Z] 18:13:03     INFO - |                                              | OK      |          |
[task 2022-09-15T18:13:03.363Z] 18:13:03     INFO - | `Tab order navigation skips hidden subtrees` | PASS    |          |
[task 2022-09-15T18:13:03.363Z] 18:13:03     INFO - 
[task 2022-09-15T18:13:03.363Z] 18:13:03     INFO - ## Slow tests ##
[task 2022-09-15T18:13:03.363Z] 18:13:03     INFO - 
[task 2022-09-15T18:13:03.364Z] 18:13:03     INFO - |                                Test                               | Result | Longest duration (ms) | Timeout (ms) |
[task 2022-09-15T18:13:03.364Z] 18:13:03     INFO - |-------------------------------------------------------------------|--------|-----------------------|--------------|
[task 2022-09-15T18:13:03.365Z] 18:13:03     INFO - | `/css/css-contain/content-visibility/content-visibility-047.html` | `OK`   | `9374`                | `10000`      |
[task 2022-09-15T18:13:03.365Z] 18:13:03     INFO - 
[task 2022-09-15T18:13:03.365Z] 18:13:03     INFO - ::: Running tests in a loop 10 times : PASS
[task 2022-09-15T18:13:03.366Z] 18:13:03     INFO - ::: Running tests in a loop with restarts 5 times : PASS
[task 2022-09-15T18:13:03.366Z] 18:13:03     INFO - ::: Running tests in a loop 10 times with flags chaos_mode_flags=0xfb : PASS
[task 2022-09-15T18:13:03.366Z] 18:13:03     INFO - ::: Running tests in a loop with restarts 5 times with flags chaos_mode_flags=0xfb : FAIL
[task 2022-09-15T18:13:03.367Z] 18:13:03     INFO - :::
[task 2022-09-15T18:13:03.367Z] 18:13:03    ERROR - ::: Test verification FAIL
[task 2022-09-15T18:13:03.367Z] 18:13:03     INFO - :::
[task 2022-09-15T18:13:03.689Z] 18:13:03    ERROR - Return code: 1
[task 2022-09-15T18:13:03.690Z] 18:13:03    ERROR - # TBPL FAILURE #
[task 2022-09-15T18:13:03.690Z] 18:13:03  WARNING - setting return code to 2
[task 2022-09-15T18:13:03.690Z] 18:13:03    ERROR - TinderboxPrint: Per-test run of .../content-visibility-047.html<br/>: FAILURE
[task 2022-09-15T18:13:03.690Z] 18:13:03     INFO - Running post-action listener: _package_coverage_data
[task 2022-09-15T18:13:03.690Z] 18:13:03     INFO - Running post-action listener: _resource_record_post_action
[task 2022-09-15T18:13:03.690Z] 18:13:03     INFO - Running post-action listener: process_java_coverage_data
[task 2022-09-15T18:13:03.690Z] 18:13:03     INFO - Running post-action listener: stop_device
[task 2022-09-15T18:13:03.690Z] 18:13:03     INFO - [mozharness: 2022-09-15 18:13:03.690795Z] Finished run-tests step (success)
[task 2022-09-15T18:13:03.690Z] 18:13:03     INFO - Running post-run listener: _resource_record_post_run
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - Total resource usage - Wall time: 506s; CPU: 4%; Read bytes: 84516864; Write bytes: 851152896; Read time: 998; Write time: 3139
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - TinderboxPrint: CPU usage<br/>4.4%
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - TinderboxPrint: I/O read bytes / time<br/>84,516,864 / 998
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - TinderboxPrint: I/O write bytes / time<br/>851,152,896 / 3,139
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - TinderboxPrint: CPU idle<br/>5,772.3 (95.1%)
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - TinderboxPrint: CPU system<br/>112.9 (1.9%)
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - TinderboxPrint: CPU user<br/>182.6 (3.0%)
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - TinderboxPrint: Swap in / out<br/>331,759,616 / 0
[task 2022-09-15T18:13:03.790Z] 18:13:03     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-09-15T18:13:03.790Z] 18:13:03     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-09-15T18:13:03.791Z] 18:13:03     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-09-15T18:13:03.791Z] 18:13:03     INFO - install - Wall time: 20s; CPU: 14%; Read bytes: 261895680; Write bytes: 265482240; Read time: 17215; Write time: 563
[task 2022-09-15T18:13:03.797Z] 18:13:03     INFO - run-tests - Wall time: 487s; CPU: 4%; Read bytes: 80379904; Write bytes: 584261632; Read time: 935; Write time: 2563
[task 2022-09-15T18:13:03.916Z] 18:13:03  WARNING - returning nonzero exit status 2
[taskcluster 2022-09-15T18:13:04.204Z]    Exit Code: 2
[taskcluster 2022-09-15T18:13:04.204Z]    User Time: 3m7.321765s
[taskcluster 2022-09-15T18:13:04.204Z]  Kernel Time: 53.692144s
[taskcluster 2022-09-15T18:13:04.204Z]    Wall Time: 9m43.189053s
[taskcluster 2022-09-15T18:13:04.204Z]       Result: FAILED
[taskcluster 2022-09-15T18:13:04.204Z] === Task Finished ===
[taskcluster 2022-09-15T18:13:04.204Z] Task Duration: 9m43.19249s
[taskcluster 2022-09-15T18:13:04.310Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-09-15T17:46:26.067Z
[taskcluster 2022-09-15T18:13:04.526Z] 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-09-15T17:46:26.067Z
[taskcluster 2022-09-15T18:13:05.194Z] 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-09-15T17:46:26.067Z
[taskcluster 2022-09-15T18:13:05.294Z] 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-09-15T17:46:26.067Z
[taskcluster 2022-09-15T18:13:05.652Z] 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-09-15T17:46:26.067Z
[taskcluster 2022-09-15T18:13:05.762Z] 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-09-15T17:46:26.067Z
[taskcluster 2022-09-15T18:13:05.874Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FlJSL8W4ScWcul_jwAjORw/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-09-15T17:46:26.067Z
[taskcluster:error] exit status 2

:mrobinson, since you are the author of the regressor, bug 1790993, could you take a look?

For more information, please visit auto_nag documentation.

Flags: needinfo?(mrobinson)

Quoting the log:

INFO - ## Slow tests ##
INFO - 
INFO - |                                Test                               | Result | Longest duration (ms) | Timeout (ms) |
INFO - |-------------------------------------------------------------------|--------|-----------------------|--------------|
INFO - | `/css/css-contain/content-visibility/content-visibility-047.html` | `OK`   | `9374`                | `10000`      |
[...]
INFO - ::: Running tests in a loop with restarts 5 times with flags chaos_mode_flags=0xfb : FAIL
INFO - :::
ERROR - ::: Test verification FAIL

This is bug 1734020.

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