Closed Bug 1829534 Opened 2 years ago Closed 2 years ago

Intermittent TCw TEST-UNEXPECTED-TIMEOUT | /fenced-frame/sandboxed-features-printdialog.https.html | TestRunner hit external timeout (this may indicate a hang)

Categories

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

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=413458594&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/P7lHFXUYRqqCc-cZ16bbBA/runs/0/artifacts/public/logs/live_backing.log


[task 2023-04-23T10:55:27.426Z] 10:55:27     INFO - TEST-START | /fenced-frame/sandboxed-features-printdialog.https.html
[task 2023-04-23T10:55:27.881Z] 10:55:27     INFO - PID 4900 | console.error: (new TypeError("can't access property \"find\", this._searchProviderInfo is null", "resource:///modules/SearchSERPTelemetry.sys.mjs", 590))
[task 2023-04-23T10:55:27.975Z] 10:55:27     INFO - PID 4900 | [CodeCoverage] Requested flush for 4840.
[task 2023-04-23T10:55:29.418Z] 10:55:29     INFO - PID 4900 | [CodeCoverage] flush completed.
[task 2023-04-23T10:55:33.939Z] 10:55:33     INFO - PID 4900 | [CodeCoverage] JS flush completed.
[task 2023-04-23T10:55:33.941Z] 10:55:33     INFO - PID 4900 | [CodeCoverage] Requested flush for 8784.
[task 2023-04-23T10:55:33.942Z] 10:55:33     INFO - PID 4900 | [CodeCoverage] Requested flush for 7600.
[task 2023-04-23T10:55:33.942Z] 10:55:33     INFO - PID 4900 | [CodeCoverage] Requested flush for 1420.
[task 2023-04-23T10:55:33.943Z] 10:55:33     INFO - PID 4900 | [CodeCoverage] Requested flush for 10200.
[task 2023-04-23T10:55:33.943Z] 10:55:33     INFO - PID 4900 | [CodeCoverage] Requested flush for 4736.
[task 2023-04-23T10:55:35.728Z] 10:55:35     INFO - PID 4900 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-04-23T10:55:45.503Z] 10:55:45     INFO - PID 4900 | console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
[task 2023-04-23T10:55:52.016Z] 10:55:52     INFO - PID 4900 | [CodeCoverage] flush completed.
[task 2023-04-23T10:55:52.032Z] 10:55:52     INFO - PID 4900 | [CodeCoverage] JS flush completed.
[task 2023-04-23T10:55:54.370Z] 10:55:54     INFO - PID 4900 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-04-23T10:55:54.385Z] 10:55:54     INFO - PID 4900 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-04-23T10:55:54.385Z] 10:55:54     INFO - PID 4900 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-04-23T10:55:56.899Z] 10:55:56     INFO - PID 4900 | [CodeCoverage] flush completed.
[task 2023-04-23T10:55:58.183Z] 10:55:58     INFO - PID 4900 | [CodeCoverage] JS flush completed.
[task 2023-04-23T10:56:02.435Z] 10:56:02     INFO - Got timeout in harness
[task 2023-04-23T10:56:02.437Z] 10:56:02     INFO - TEST-UNEXPECTED-TIMEOUT | /fenced-frame/sandboxed-features-printdialog.https.html | TestRunner hit external timeout (this may indicate a hang)
[task 2023-04-23T10:56:02.437Z] 10:56:02     INFO - TEST-INFO took 35026ms
[task 2023-04-23T10:56:02.438Z] 10:56:02     INFO - No more tests
[task 2023-04-23T10:56:10.250Z] 10:56:10     INFO - PID 4900 | [CodeCoverage] flush completed.
[task 2023-04-23T10:56:10.257Z] 10:56:10     INFO - PID 4900 | [CodeCoverage] JS flush completed.
[task 2023-04-23T10:56:12.384Z] 10:56:12     INFO - PID 4900 | [CodeCoverage] flush completed.
[task 2023-04-23T10:56:12.400Z] 10:56:12     INFO - PID 4900 | [CodeCoverage] JS flush completed.
[task 2023-04-23T10:56:14.204Z] 10:56:14     INFO - PID 4900 | [CodeCoverage] flush completed.
[task 2023-04-23T10:56:14.215Z] 10:56:14     INFO - PID 4900 | [CodeCoverage] JS flush completed.
[task 2023-04-23T10:57:13.826Z] 10:57:13     INFO - Browser exited with return code 572
[task 2023-04-23T10:57:23.831Z] 10:57:23  WARNING - Forcibly terminating runner process
[task 2023-04-23T10:57:23.862Z] 10:57:23     INFO - SUITE-END | took 149s
[task 2023-04-23T10:57:23.867Z] 10:57:23     INFO - Got 1 unexpected results, with 0 unexpected passes
[task 2023-04-23T10:57:23.869Z] 10:57:23     INFO - wptserve Stopped WebTransport over HTTP/3 server on 127.0.0.1:11000
[task 2023-04-23T10:57:23.894Z] 10:57:23     INFO - wptserve Stopped http server on 127.0.0.1:8443
[task 2023-04-23T10:57:24.098Z] 10:57:24     INFO - wptserve Stopped http server on 127.0.0.1:8000
[task 2023-04-23T10:57:24.100Z] 10:57:24     INFO - wptserve Stopped http server on 127.0.0.1:8001
[task 2023-04-23T10:57:24.100Z] 10:57:24     INFO - wptserve Stopped http server on 127.0.0.1:8002
[task 2023-04-23T10:57:24.144Z] 10:57:24     INFO - wptserve Stopped http server on 127.0.0.1:8003
[task 2023-04-23T10:57:24.144Z] 10:57:24     INFO - wptserve Stopped http server on 127.0.0.1:8445
[task 2023-04-23T10:57:24.144Z] 10:57:24     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
[task 2023-04-23T10:57:24.144Z] 10:57:24     INFO - wptserve Stopped http server on 127.0.0.1:8444
[task 2023-04-23T10:57:24.148Z] 10:57:24     INFO - wptserve Stopped http server on 127.0.0.1:8446
[task 2023-04-23T10:57:24.254Z] 10:57:24     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
[task 2023-04-23T10:57:24.256Z] 10:57:24     INFO - wptserve Stopped http server on 127.0.0.1:9000
[task 2023-04-23T10:57:24.286Z] 10:57:24     INFO - Removed font: Ahem.ttf
[task 2023-04-23T10:57:24.364Z] 10:57:24     INFO - Closing logging queue
[task 2023-04-23T10:57:24.379Z] 10:57:24     INFO - queue closed
[task 2023-04-23T10:57:24.755Z] 10:57:24     INFO - Return code: 1
[task 2023-04-23T10:57:24.911Z] 10:57:24     INFO - Running post-action listener: _package_coverage_data
[task 2023-04-23T10:57:24.911Z] 10:57:24     INFO - No tests were found...not saving coverage data.
[task 2023-04-23T10:57:24.911Z] 10:57:24     INFO - Running post-action listener: _resource_record_post_action
[task 2023-04-23T10:57:24.911Z] 10:57:24     INFO - Running post-action listener: process_java_coverage_data
[task 2023-04-23T10:57:24.911Z] 10:57:24     INFO - Running post-action listener: stop_device
[task 2023-04-23T10:57:24.911Z] 10:57:24     INFO - [mozharness: 2023-04-23 10:57:24.911712Z] Finished run-tests step (failed)
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL - Uncaught exception: Traceback (most recent call last):
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -   File "Z:\task_168224647758082\mozharness\mozharness\base\script.py", line 2393, in run
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -     self.run_action(action)
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -   File "Z:\task_168224647758082\mozharness\mozharness\base\script.py", line 2327, in run_action
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -     self._possibly_run_method(method_name, error_if_missing=True)
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -   File "Z:\task_168224647758082\mozharness\mozharness\base\script.py", line 2279, in _possibly_run_method
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -     return getattr(self, method_name)()
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -   File "Z:\task_168224647758082\mozharness\scripts\web_platform_tests.py", line 649, in run_tests
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -     self.add_per_test_coverage_report(
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -   File "Z:\task_168224647758082\mozharness\mozharness\mozilla\testing\codecoverage.py", line 368, in add_per_test_coverage_report
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -     grcov_file = self.parse_coverage_artifacts(
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -   File "Z:\task_168224647758082\mozharness\mozharness\mozilla\testing\codecoverage.py", line 303, in parse_coverage_artifacts
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL -     jsvm_files = [os.path.join(jsvm_dir, e) for e in os.listdir(jsvm_dir)]
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL - FileNotFoundError: [WinError 3] The system cannot find the path specified: 'C:\\Users\\task_168224647758082\\AppData\\Local\\Temp\\tmp0wkeu1vf'
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL - Running post_fatal callback...
[task 2023-04-23T10:57:24.917Z] 10:57:24    FATAL - Exiting -1
[task 2023-04-23T10:57:24.917Z] 10:57:24     INFO - Running post-run listener: _resource_record_post_run
[task 2023-04-23T10:57:25.068Z] 10:57:25     INFO - Total resource usage - Wall time: 198s; CPU: 23%; Read bytes: 444368384; Write bytes: 1406685696; Read time: 137; Write time: 121
[task 2023-04-23T10:57:25.068Z] 10:57:25     INFO - TinderboxPrint: CPU usage<br/>22.5%
[task 2023-04-23T10:57:25.068Z] 10:57:25     INFO - TinderboxPrint: I/O read bytes / time<br/>444,368,384 / 137
[task 2023-04-23T10:57:25.068Z] 10:57:25     INFO - TinderboxPrint: I/O write bytes / time<br/>1,406,685,696 / 121
[task 2023-04-23T10:57:25.078Z] 10:57:25     INFO - TinderboxPrint: CPU idle<br/>1,225.5 (77.5%)
[task 2023-04-23T10:57:25.078Z] 10:57:25     INFO - TinderboxPrint: CPU system<br/>124.6 (7.9%)
[task 2023-04-23T10:57:25.078Z] 10:57:25     INFO - TinderboxPrint: CPU user<br/>230.7 (14.6%)
[task 2023-04-23T10:57:25.078Z] 10:57:25     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-04-23T10:57:25.078Z] 10:57:25     INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-04-23T10:57:25.078Z] 10:57:25     INFO - verify-device - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-04-23T10:57:25.079Z] 10:57:25     INFO - install - Wall time: 4s; CPU: 32%; Read bytes: 3550208; Write bytes: 262778880; Read time: 0; Write time: 4
[task 2023-04-23T10:57:25.080Z] 10:57:25     INFO - run-tests - Wall time: 194s; CPU: 22%; Read bytes: 440818176; Write bytes: 984207872; Read time: 137; Write time: 116
[taskcluster 2023-04-23T10:57:25.568Z]    Exit Code: 4294967295
[taskcluster 2023-04-23T10:57:25.568Z]    User Time: 0s
[taskcluster 2023-04-23T10:57:25.568Z]  Kernel Time: 0s
[taskcluster 2023-04-23T10:57:25.568Z]    Wall Time: 6m29.4635639s
[taskcluster 2023-04-23T10:57:25.568Z]       Result: FAILED
[taskcluster 2023-04-23T10:57:25.568Z] === Task Finished ===
[taskcluster 2023-04-23T10:57:25.568Z] Task Duration: 6m29.4710161s
[taskcluster 2023-04-23T10:57:25.683Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-22T09:17:35.781Z
[taskcluster 2023-04-23T10:57:26.149Z] 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-22T09:17:35.781Z
[taskcluster 2023-04-23T10:57:26.478Z] 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-22T09:17:35.781Z
[taskcluster 2023-04-23T10:57:26.839Z] 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-22T09:17:35.781Z
[taskcluster 2023-04-23T10:57:27.026Z] 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-22T09:17:35.781Z
[taskcluster 2023-04-23T10:57:27.233Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2023-07-22T09:17:35.781Z
[taskcluster:error] exit status 0xffffffff
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.