Open Bug 1839573 Opened 2 years ago Updated 4 days ago

Intermittent wpt Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_168732087894746/build/venv/bin/python', '-u', '/opt/worker/tasks/task_168732087894746/build/tests/web-platform/runtests.py', '--log-raw=-'

Categories

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

defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned, NeedInfo)

References

Details

(Keywords: intermittent-failure)

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


[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'RUN_ID': '0',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'RUST_BACKTRACE': 'full',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'SCCACHE_DISABLE': '1',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'SHELL': '/bin/bash',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'SHLVL': '1',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.TllCIvaBVC/Listeners',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'TASK_ID': 'eB6fEpRGS_Ssnz5JX0ZPvQ',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'TESTS_BY_MANIFEST_URL': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QBa1GD6oQw-Lz1SjWteOVg/artifacts/public/tests-by-manifest.json.gz',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'TMPDIR': '/var/folders/4b/88tf73017fqgw4z3qbkfcbym000014/T/',
[task 2023-06-21T04:24:57.695Z] 04:24:57     INFO -  'USER': 'cltbld',
[task 2023-06-21T04:24:57.696Z] 04:24:57     INFO -  'VIRTUAL_ENV': 'venv',
[task 2023-06-21T04:24:57.696Z] 04:24:57     INFO -  'XPC_FLAGS': '0x0',
[task 2023-06-21T04:24:57.696Z] 04:24:57     INFO -  'XPC_SERVICE_NAME': '0',
[task 2023-06-21T04:24:57.696Z] 04:24:57     INFO -  '_': '/usr/local/bin/start-worker',
[task 2023-06-21T04:24:57.696Z] 04:24:57     INFO -  '__CF_USER_TEXT_ENCODING': '0x24:0x0:0x0'}
[task 2023-06-21T04:24:57.697Z] 04:24:57     INFO - Calling ['/opt/worker/tasks/task_168732087894746/build/venv/bin/python', '-u', '/opt/worker/tasks/task_168732087894746/build/tests/web-platform/runtests.py', '--log-raw=-', '--log-wptreport=/opt/worker/tasks/task_168732087894746/build/blobber_upload_dir/wptreport.json', '--log-errorsummary=/opt/worker/tasks/task_168732087894746/build/blobber_upload_dir/wpt_errorsummary.log', '--symbols-path=/opt/worker/tasks/task_168732087894746/build/symbols', '--stackwalk-binary=/opt/worker/tasks/task_168732087894746/fetches/minidump-stackwalk/minidump-stackwalk', '--stackfix-dir=/opt/worker/tasks/task_168732087894746/build/tests/bin', '--no-pause-after-test', '--instrument-to-file=/opt/worker/tasks/task_168732087894746/build/blobber_upload_dir/wpt_instruments.txt', '--specialpowers-path=/opt/worker/tasks/task_168732087894746/build/tests/extensions/specialpowers@mozilla.org.xpi', '--processes=1', '--binary=/opt/worker/tasks/task_168732087894746/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox', '--install-fonts', '--test-type=reftest', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--skip-implementation-status=backlog', '--skip-implementation-status=not-implementing', '--test-groups=/opt/worker/tasks/task_168732087894746/fetches/wpt_tests_by_group.json', '--prefs-root=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/prefs', '--config=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/wptrunner.ini', '--ca-cert-path=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/tests/tools/certs/cacert.pem', '--host-key-path=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/tests/tools/certs/web-platform.test.key', '--host-cert-path=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/tests/tools/certs/web-platform.test.pem', '--certutil-binary=/opt/worker/tasks/task_168732087894746/build/tests/bin/certutil', '/mathml/presentation-markup/mrow', '/css/css-ui', '/svg/extensibility/foreignObject', '/css/css-text', '/shadow-dom/untriaged/styles', '/html/semantics/document-metadata', '/css/filter-effects/filter-function', '/html/rendering/replaced-elements', '/html/semantics/text-level-semantics', '/css/css-counter-styles/trad-chinese-formal', '/_mozilla/infrastructure/prefs', '/css/css-counter-styles/devanagari', '/css/CSS2/normal-flow', '/css/css-contain/content-visibility', '/css/css-align/content-distribution', '/mathml/relations/text-and-math', '/mathml/presentation-markup/spaces', '/svg/render/reftests', '/service-workers/service-worker', '/acid/acid3', '/css/css-counter-styles/tamil', '/css/css-flexbox/order', '/quirks', '/css/css-transforms/skewY', '/dom/xslt', '/css/css-scroll-anchoring', '/css/CSS2/linebox', '/css/css-inline', '/css/css-backgrounds/background-attachment-local', '/css/css-counter-styles/lower-roman', '/css/css-counter-styles/japanese-formal', '/css/css-text/word-spacing', '/fullscreen/rendering', '/css/css-text/text-transform', '/css/CSS2/colors', '/svg/path/distance', '/css/css-view-transitions', '/css/css-transforms/animation', '/css/css-pseudo', '/css/css-counter-styles/korean-hanja-informal', '/css/css-grid/masonry', '/css/css-transforms/group', '/svg/styling/render', '/css/css-position/multicol', '/css/css-transforms/translate', '/css/CSS2/zorder', '/css/css-grid/abspos', '/css/css-layout-api/layout-child', '/css/css-overflow', '/css/css-shadow-parts', '/css/css-backgrounds/background-size', '/css/CSS2/tables', '/html/semantics/interactive-elements', '/css/css-counter-styles/oriya', '/css/css-counter-styles/cjk-earthly-branch', '/css/css-text/text-encoding', '/css/compositing/mix-blend-mode', '/infrastructure/assumptions', '/css/css-logical', '/css/css-text/bidi', '/css/css-layout-api/edges', '/svg/painting', '/css/CSS2/box', '/css/css-color/animation', '/css/css-images', '/css/css-transforms/patternTransform', '/css/css-flexbox', '/css/css-sizing/aspect-ratio', '/density-size-correction', '/_mozilla/css', '/css/css-layout-api/auto-block-size', '/css/css-masking/clip-rule', '/css/CSS2/floats', '/resize-observer', '/css/css-break/table', '/svg/shapes/reftests', '/html/infrastructure/common-microsyntaxes', '/css/css-anchor-position', '/css/CSS2/abspos', '/web-animations/timing-model/animations', '/css/css-display', '/css/css-text/overflow-wrap', '/css/selectors/invalidation', '/css/css-box/margin-trim', '/css/css-fonts/matching', '/css/css-grid/grid-items', '/css/css-multicol/table', '/css/css-counter-styles/gurmukhi', '/css/css-writing-modes/forms', '/css/css-counter-styles/armenian', '/css/css-text/i18n', '/css/CSS2/selector', '/css/printing', '/css/css-counter-styles/katakana-iroha', '/mathml/presentation-markup/direction', '/html/dom/directionality', '/fetch/http-cache', '/css/css-tables', '/compat', '/css/CSS2/visudet'] with output_timeout 1000
[task 2023-06-21T04:25:00.804Z] 04:25:00     INFO - mozversion application_buildid: 20230621040008
[task 2023-06-21T04:25:00.804Z] 04:25:00     INFO - mozversion application_changeset: 07613976379f96a9416021b138ba21870fe2065d
[task 2023-06-21T04:25:00.804Z] 04:25:00     INFO - mozversion application_display_name: Firefox Nightly
[task 2023-06-21T04:25:00.804Z] 04:25:00     INFO - mozversion application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
[task 2023-06-21T04:25:00.805Z] 04:25:00     INFO - mozversion application_name: Firefox
[task 2023-06-21T04:25:00.805Z] 04:25:00     INFO - mozversion application_remotingname: firefox-default
[task 2023-06-21T04:25:00.805Z] 04:25:00     INFO - mozversion application_repository: https://hg.mozilla.org/mozilla-central
[task 2023-06-21T04:25:00.805Z] 04:25:00     INFO - mozversion application_vendor: Mozilla
[task 2023-06-21T04:25:00.806Z] 04:25:00     INFO - mozversion application_version: 116.0a1
[task 2023-06-21T04:25:00.806Z] 04:25:00     INFO - mozversion platform_buildid: 20230621040008
[task 2023-06-21T04:25:00.806Z] 04:25:00     INFO - mozversion platform_changeset: 07613976379f96a9416021b138ba21870fe2065d
[task 2023-06-21T04:25:00.806Z] 04:25:00     INFO - mozversion platform_repository: https://hg.mozilla.org/mozilla-central
[task 2023-06-21T04:25:00.806Z] 04:25:00     INFO - mozversion platform_version: 116.0a1
[task 2023-06-21T04:41:41.033Z] 04:41:41     INFO - Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_168732087894746/build/venv/bin/python', '-u', '/opt/worker/tasks/task_168732087894746/build/tests/web-platform/runtests.py', '--log-raw=-', '--log-wptreport=/opt/worker/tasks/task_168732087894746/build/blobber_upload_dir/wptreport.json', '--log-errorsummary=/opt/worker/tasks/task_168732087894746/build/blobber_upload_dir/wpt_errorsummary.log', '--symbols-path=/opt/worker/tasks/task_168732087894746/build/symbols', '--stackwalk-binary=/opt/worker/tasks/task_168732087894746/fetches/minidump-stackwalk/minidump-stackwalk', '--stackfix-dir=/opt/worker/tasks/task_168732087894746/build/tests/bin', '--no-pause-after-test', '--instrument-to-file=/opt/worker/tasks/task_168732087894746/build/blobber_upload_dir/wpt_instruments.txt', '--specialpowers-path=/opt/worker/tasks/task_168732087894746/build/tests/extensions/specialpowers@mozilla.org.xpi', '--processes=1', '--binary=/opt/worker/tasks/task_168732087894746/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox', '--install-fonts', '--test-type=reftest', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--skip-implementation-status=backlog', '--skip-implementation-status=not-implementing', '--test-groups=/opt/worker/tasks/task_168732087894746/fetches/wpt_tests_by_group.json', '--prefs-root=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/prefs', '--config=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/wptrunner.ini', '--ca-cert-path=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/tests/tools/certs/cacert.pem', '--host-key-path=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/tests/tools/certs/web-platform.test.key', '--host-cert-path=/opt/worker/tasks/task_168732087894746/build/tests/web-platform/tests/tools/certs/web-platform.test.pem', '--certutil-binary=/opt/worker/tasks/task_168732087894746/build/tests/bin/certutil', '/mathml/presentation-markup/mrow', '/css/css-ui', '/svg/extensibility/foreignObject', '/css/css-text', '/shadow-dom/untriaged/styles', '/html/semantics/document-metadata', '/css/filter-effects/filter-function', '/html/rendering/replaced-elements', '/html/semantics/text-level-semantics', '/css/css-counter-styles/trad-chinese-formal', '/_mozilla/infrastructure/prefs', '/css/css-counter-styles/devanagari', '/css/CSS2/normal-flow', '/css/css-contain/content-visibility', '/css/css-align/content-distribution', '/mathml/relations/text-and-math', '/mathml/presentation-markup/spaces', '/svg/render/reftests', '/service-workers/service-worker', '/acid/acid3', '/css/css-counter-styles/tamil', '/css/css-flexbox/order', '/quirks', '/css/css-transforms/skewY', '/dom/xslt', '/css/css-scroll-anchoring', '/css/CSS2/linebox', '/css/css-inline', '/css/css-backgrounds/background-attachment-local', '/css/css-counter-styles/lower-roman', '/css/css-counter-styles/japanese-formal', '/css/css-text/word-spacing', '/fullscreen/rendering', '/css/css-text/text-transform', '/css/CSS2/colors', '/svg/path/distance', '/css/css-view-transitions', '/css/css-transforms/animation', '/css/css-pseudo', '/css/css-counter-styles/korean-hanja-informal', '/css/css-grid/masonry', '/css/css-transforms/group', '/svg/styling/render', '/css/css-position/multicol', '/css/css-transforms/translate', '/css/CSS2/zorder', '/css/css-grid/abspos', '/css/css-layout-api/layout-child', '/css/css-overflow', '/css/css-shadow-parts', '/css/css-backgrounds/background-size', '/css/CSS2/tables', '/html/semantics/interactive-elements', '/css/css-counter-styles/oriya', '/css/css-counter-styles/cjk-earthly-branch', '/css/css-text/text-encoding', '/css/compositing/mix-blend-mode', '/infrastructure/assumptions', '/css/css-logical', '/css/css-text/bidi', '/css/css-layout-api/edges', '/svg/painting', '/css/CSS2/box', '/css/css-color/animation', '/css/css-images', '/css/css-transforms/patternTransform', '/css/css-flexbox', '/css/css-sizing/aspect-ratio', '/density-size-correction', '/_mozilla/css', '/css/css-layout-api/auto-block-size', '/css/css-masking/clip-rule', '/css/CSS2/floats', '/resize-observer', '/css/css-break/table', '/svg/shapes/reftests', '/html/infrastructure/common-microsyntaxes', '/css/css-anchor-position', '/css/CSS2/abspos', '/web-animations/timing-model/animations', '/css/css-display', '/css/css-text/overflow-wrap', '/css/selectors/invalidation', '/css/css-box/margin-trim', '/css/css-fonts/matching', '/css/css-grid/grid-items', '/css/css-multicol/table', '/css/css-counter-styles/gurmukhi', '/css/css-writing-modes/forms', '/css/css-counter-styles/armenian', '/css/css-text/i18n', '/css/CSS2/selector', '/css/printing', '/css/css-counter-styles/katakana-iroha', '/mathml/presentation-markup/direction', '/html/dom/directionality', '/fetch/http-cache', '/css/css-tables', '/compat', '/css/CSS2/visudet']
[taskcluster:error] Aborting task...
[taskcluster:warn 2023-06-21T05:50:14.198Z] no such process
[taskcluster 2023-06-21T05:50:14.198Z] === Task Finished ===
[taskcluster 2023-06-21T05:50:14.198Z] Task Duration: 1h30m0.266921s
[taskcluster 2023-06-21T05:50:14.260Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-09-19T04:03:38.710Z
[taskcluster 2023-06-21T05:50:14.480Z] Uploading artifact public/test_info/wpt_errorsummary.log from file build/blobber_upload_dir/wpt_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2023-09-19T04:03:38.710Z
[taskcluster 2023-06-21T05:50:14.571Z] 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-19T04:03:38.710Z
[taskcluster 2023-06-21T05:50:14.655Z] 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-19T04:03:38.710Z
[taskcluster 2023-06-21T05:50:14.762Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eB6fEpRGS_Ssnz5JX0ZPvQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-09-19T04:03:38.710Z
[taskcluster:error] Task aborted - max run time exceeded

This is a continuation of bug 1612600, after the error message was changed from "mozprocess timed out ..." to "mozharness timed out ..."

Component: Applications: MozharnessCore → web-platform-tests
Product: Release Engineering → Testing
See Also: → 1612600
Summary: Intermittent Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_168732087894746/build/venv/bin/python', '-u', '/opt/worker/tasks/task_168732087894746/build/tests/web-platform/runtests.py', '--log-raw=-' → Intermittent wpt Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_168732087894746/build/venv/bin/python', '-u', '/opt/worker/tasks/task_168732087894746/build/tests/web-platform/runtests.py', '--log-raw=-'
Status: NEW → RESOLVED
Closed: 8 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

These days only our macOS workers seem to be affected here. The hang always happens when mozversion logged the details of Firefox:
https://treeherder.mozilla.org/logviewer?job_id=550096318&repo=autoland&lineNumber=805-806

[task 2026-02-22T20:08:01.822+00:00] 20:08:01     INFO - mozversion platform_version: 149.0a1
[task 2026-02-22T20:24:42.098+00:00] 20:24:42     INFO - Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_177179044075000/build/venv/bin/python', '-u', '/opt/worker/tasks/task_177179044075000/build/tests/web-platform/runtests.py', '--log-raw=-',  ..
[task 2026-02-22T20:24:42.129+00:00] 20:24:42     INFO - Return code: -9
[task 2026-02-22T20:24:42.129+00:00] 20:24:42    ERROR - No suite end message was emitted by this harness.

In case when it's working the following output can be seen:
https://treeherder.mozilla.org/logviewer?job_id=550096540&repo=autoland&task=UKMEuiPES22RLsDHwD3hQQ.0&lineNumber=813-814

[task 2026-02-22T20:10:13.269+00:00] 20:10:13     INFO - mozversion platform_version: 149.0a1
[task 2026-02-22T20:10:27.669+00:00] 20:10:27     INFO - wptserve Starting http server on http://127.0.0.1:8001

So maybe there is a hang in Python around starting wptserve? At least the profile as generated from the resource usage data doesn't show anything particular that there was unusual CPU load during the whole execution time.

James, any idea what this could be?

Flags: needinfo?(james)

Oh, in the marker table of the profile there is actually one entry which shows that we run another command after mozversion:

DEBUG — git rev-parse --show-toplevel —

Maybe that one causes the hang. Usually it takes around 14s to run this command (as reported by the profile).

You need to log in before you can comment on or make changes to this bug.