1835183 - Intermittent TV caught OS error None: None while running ['Z:\\task_168505235909981\\build\\venv\\Scripts\\python', '-u', 'Z:\\task_168505235909981\\build\\tests\\web-platform\\runtests.py', '--log-raw=-', '--log-wptreport=Z:\\task_168505235909981\\b

Status: RESOLVED DUPLICATE of bug 1834900

(Testing :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-05-25T23:13:25.136Z] 23:13:25     INFO - TEST-PASS | leakcheck | utility no leaks detected!
[task 2023-05-25T23:13:25.138Z] 23:13:25     INFO - Closing logging queue
[task 2023-05-25T23:13:25.139Z] 23:13:25     INFO - queue closed
[task 2023-05-25T23:13:25.140Z] 23:13:25  WARNING - Firefox didn't exit cleanly, not processing leak logs
[task 2023-05-25T23:13:25.170Z] Exception in thread ProcessReader:
[task 2023-05-25T23:13:25.170Z] Traceback (most recent call last):
[task 2023-05-25T23:13:25.170Z]   File "c:\mozilla-build\python3\lib\threading.py", line 973, in _bootstrap_inner
[task 2023-05-25T23:13:25.176Z]     self.run()
[task 2023-05-25T23:13:25.176Z]   File "c:\mozilla-build\python3\lib\threading.py", line 910, in run
[task 2023-05-25T23:13:25.177Z]     self._target(*self._args, **self._kwargs)
[task 2023-05-25T23:13:25.177Z]   File "Z:\task_168505235909981\mozharness\mozprocess\processhandler.py", line 1160, in _read
[task 2023-05-25T23:13:25.177Z]     callback(line.rstrip())
[task 2023-05-25T23:13:25.177Z]   File "Z:\task_168505235909981\mozharness\mozprocess\processhandler.py", line 1066, in __call__
[task 2023-05-25T23:13:25.178Z]     e(*args, **kwargs)
[task 2023-05-25T23:13:25.178Z]   File "Z:\task_168505235909981\mozharness\mozharness\base\script.py", line 1600, in processOutput
[task 2023-05-25T23:13:25.178Z]     parser.add_lines(line)
[task 2023-05-25T23:13:25.178Z]   File "Z:\task_168505235909981\mozharness\mozharness\base\log.py", line 371, in add_lines
[task 2023-05-25T23:13:25.179Z]     self.parse_single_line(line)
[task 2023-05-25T23:13:25.179Z]   File "Z:\task_168505235909981\mozharness\mozharness\mozilla\structuredlog.py", line 124, in parse_single_line
[task 2023-05-25T23:13:25.179Z]     log_data = self.formatter(data)
[task 2023-05-25T23:13:25.179Z]   File "Z:\task_168505235909981\build\venv\Lib\site-packages\mozlog\formatters\tbplformatter.py", line 47, in __call__
[task 2023-05-25T23:13:25.179Z]     return super(TbplFormatter, self).__call__(data)
[task 2023-05-25T23:13:25.179Z]   File "Z:\task_168505235909981\build\venv\Lib\site-packages\mozlog\reader.py", line 72, in __call__
[task 2023-05-25T23:13:25.179Z]     return handler(data)
[task 2023-05-25T23:13:25.179Z]   File "Z:\task_168505235909981\build\venv\Lib\site-packages\mozlog\formatters\tbplformatter.py", line 311, in suite_end
[task 2023-05-25T23:13:25.180Z]     time = int((data["time"] - start_time) / 1000)
[task 2023-05-25T23:13:25.180Z] TypeError: unsupported operand type(s) for -: 'int' and 'NoneType'
[task 2023-05-25T23:16:55.232Z] Traceback (most recent call last):
[task 2023-05-25T23:16:55.232Z]   File "Z:\task_168505235909981\mozharness\mozprocess\processhandler.py", line 640, in _custom_wait
[task 2023-05-25T23:16:55.232Z]     item = self._process_events.get(timeout=timeout)
[task 2023-05-25T23:16:55.232Z]   File "c:\mozilla-build\python3\lib\queue.py", line 179, in get
[task 2023-05-25T23:16:55.232Z]     raise Empty
[task 2023-05-25T23:16:55.232Z] _queue.Empty
[task 2023-05-25T23:16:55.243Z] 23:16:55    ERROR - caught OS error None: None while running ['Z:\\task_168505235909981\\build\\venv\\Scripts\\python', '-u', 'Z:\\task_168505235909981\\build\\tests\\web-platform\\runtests.py', '--log-raw=-', '--log-wptreport=Z:\\task_168505235909981\\build\\blobber_upload_dir\\wptreport.json', '--log-errorsummary=Z:\\task_168505235909981\\build\\blobber_upload_dir\\wpt-test1_errorsummary.log', '--symbols-path=Z:\\task_168505235909981\\build\\symbols', '--stackwalk-binary=Z:/task_168505235909981/fetches\\minidump-stackwalk\\minidump-stackwalk.exe', '--stackfix-dir=Z:\\task_168505235909981\\build\\tests\\bin', '--no-pause-after-test', '--instrument-to-file=Z:\\task_168505235909981\\build\\blobber_upload_dir\\wpt_instruments.txt', '--specialpowers-path=Z:\\task_168505235909981\\build\\tests\\extensions\\[e-mail]', '--processes=1', '--binary=Z:\\task_168505235909981\\build\\application\\firefox\\firefox.exe', '--install-fonts', '--test-type=testharness', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--prefs-root=Z:\\task_168505235909981\\build\\tests\\web-platform\\prefs', '--config=Z:\\task_168505235909981\\build\\tests\\web-platform\\wptrunner.ini', '--ca-cert-path=Z:\\task_168505235909981\\build\\tests\\web-platform\\tests\\tools\\certs\\cacert.pem', '--host-key-path=Z:\\task_168505235909981\\build\\tests\\web-platform\\tests\\tools\\certs\\web-platform.test.key', '--host-cert-path=Z:\\task_168505235909981\\build\\tests\\web-platform\\tests\\tools\\certs\\web-platform.test.pem', '--certutil-binary=Z:\\task_168505235909981\\build\\tests\\bin\\certutil.exe', '--verify-log-full', '--verify', 'tests/web-platform/tests/css/css-backgrounds/background-image-cors-no-reload.html']
[task 2023-05-25T23:16:55.243Z] 23:16:55  WARNING - setting return code to 2
[task 2023-05-25T23:16:55.243Z] 23:16:55    ERROR - TinderboxPrint: Per-test run of ...\background-image-cors-no-reload.html<br/>: FAILURE
[task 2023-05-25T23:16:55.243Z] 23:16:55     INFO - Running post-action listener: _package_coverage_data
[task 2023-05-25T23:16:55.243Z] 23:16:55     INFO - Running post-action listener: _resource_record_post_action
[task 2023-05-25T23:16:55.243Z] 23:16:55     INFO - Running post-action listener: process_java_coverage_data
[task 2023-05-25T23:16:55.244Z] 23:16:55     INFO - Running post-action listener: stop_device
[task 2023-05-25T23:16:55.244Z] 23:16:55     INFO - [mozharness: 2023-05-25 23:16:55.244340Z] Finished run-tests step (success)
[task 2023-05-25T23:16:55.244Z] 23:16:55     INFO - Running post-run listener: _resource_record_post_run
[task 2023-05-25T23:16:55.245Z] IO Completion Port unexpectedly closed
[task 2023-05-25T23:16:55.436Z] 23:16:55     INFO - Total resource usage - Wall time: 289s; CPU: 31%; Read bytes: 89475072; Write bytes: 729094656; Read time: 1; Write time: 55
[task 2023-05-25T23:16:55.436Z] 23:16:55     INFO - TinderboxPrint: CPU usage<br/>30.7%
[task 2023-05-25T23:16:55.436Z] 23:16:55     INFO - TinderboxPrint: I/O read bytes / time<br/>89,475,072 / 1
[task 2023-05-25T23:16:55.436Z] 23:16:55     INFO - TinderboxPrint: I/O write bytes / time<br/>729,094,656 / 55
[task 2023-05-25T23:16:55.439Z] 23:16:55     INFO - TinderboxPrint: CPU idle<br/>1,603.9 (69.4%)
[task 2023-05-25T23:16:55.439Z] 23:16:55     INFO - TinderboxPrint: CPU system<br/>202.1 (8.7%)
[task 2023-05-25T23:16:55.439Z] 23:16:55     INFO - TinderboxPrint: CPU user<br/>504.5 (21.8%)
[task 2023-05-25T23:16:55.439Z] 23:16:55     INFO - pull - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-05-25T23:16:55.440Z] 23:16:55     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-05-25T23:16:55.440Z] 23:16:55     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-05-25T23:16:55.440Z] 23:16:55     INFO - install - Wall time: 3s; CPU: 32%; Read bytes: 181760; Write bytes: 55984128; Read time: 0; Write time: 2
[task 2023-05-25T23:16:55.442Z] 23:16:55     INFO - run-tests - Wall time: 287s; CPU: 31%; Read bytes: 89293312; Write bytes: 663607808; Read time: 1; Write time: 53
[task 2023-05-25T23:16:55.498Z] 23:16:55  WARNING - returning nonzero exit status 2
[taskcluster 2023-05-25T23:16:55.952Z]    Exit Code: 2
[taskcluster 2023-05-25T23:16:55.952Z]    User Time: 15.625ms
[taskcluster 2023-05-25T23:16:55.952Z]  Kernel Time: 0s
[taskcluster 2023-05-25T23:16:55.952Z]    Wall Time: 15m9.6388328s
[taskcluster 2023-05-25T23:16:55.952Z]       Result: FAILED
[taskcluster 2023-05-25T23:16:55.952Z] === Task Finished ===
[taskcluster 2023-05-25T23:16:55.952Z] Task Duration: 15m9.6424952s
[taskcluster 2023-05-25T23:16:56.306Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-05-24T22:37:49.770Z
[taskcluster 2023-05-25T23:16:57.515Z] 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 2024-05-24T22:37:49.770Z
[taskcluster 2023-05-25T23:16:58.213Z] 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 2024-05-24T22:37:49.770Z
[taskcluster 2023-05-25T23:16:58.713Z] 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 2024-05-24T22:37:49.770Z
[taskcluster 2023-05-25T23:16:59.219Z] 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 2024-05-24T22:37:49.770Z
[taskcluster 2023-05-25T23:16:59.701Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-05-24T22:37:49.770Z
[taskcluster:error] exit status 2

Comment 1

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

:emilio, since you are the author of the regressor, bug 1832528, could you take a look?

For more information, please visit BugBot documentation.

Comment 2

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

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

Comment 3

[Emilio Cobos Álvarez (:emilio)]

This doesn't seem specific to my changes, seems an issue with verify?

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

this looks to be windows debug only, and it seems to be an issue with the mozlog log parser, not the test itself.

Comment 5

[Emilio Cobos Álvarez (:emilio)]

Not sure what's the best component, feel free to move...

Comment 6

[Intermittent Failures Robot]

3 failures in 3946 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• windows11-32-2009-qr: 2
  • debug: 2
• windows11-64-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1835183&startday=2023-05-22&endday=2023-05-28&tree=all

Comment 7

[Cristian Tuns]

This might be a dupe of Bug 1834900