1846891 - Permafailing Btime [taskcluster:error] Task aborted - max run time exceeded | Could not find the metadata file in that profile

Status: RESOLVED DUPLICATE of bug 1846699

(Testing :: Performance, defect)

Description

[Treeherder Bug Filer]

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

---

[task 2023-08-03T00:15:17.679Z] 00:15:17     INFO -  condprof INFO | Verifying Desktop Firefox binary
[task 2023-08-03T00:15:17.680Z] 00:15:17     INFO -  mozversion application_buildid: 20230802220030
[task 2023-08-03T00:15:17.681Z] 00:15:17     INFO -  mozversion application_changeset: 4e8d25555f9d9253daae12f37e70b494fe6bc018
[task 2023-08-03T00:15:17.681Z] 00:15:17     INFO -  mozversion application_display_name: Firefox Nightly
[task 2023-08-03T00:15:17.681Z] 00:15:17     INFO -  mozversion application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
[task 2023-08-03T00:15:17.681Z] 00:15:17     INFO -  mozversion application_name: Firefox
[task 2023-08-03T00:15:17.681Z] 00:15:17     INFO -  mozversion application_remotingname: firefox-nightly
[task 2023-08-03T00:15:17.681Z] 00:15:17     INFO -  mozversion application_repository: https://hg.mozilla.org/mozilla-central
[task 2023-08-03T00:15:17.681Z] 00:15:17     INFO -  mozversion application_vendor: Mozilla
[task 2023-08-03T00:15:17.682Z] 00:15:17     INFO -  mozversion application_version: 118.0a1
[task 2023-08-03T00:15:17.682Z] 00:15:17     INFO -  mozversion platform_buildid: 20230802220030
[task 2023-08-03T00:15:17.682Z] 00:15:17     INFO -  mozversion platform_changeset: 4e8d25555f9d9253daae12f37e70b494fe6bc018
[task 2023-08-03T00:15:17.682Z] 00:15:17     INFO -  mozversion platform_repository: https://hg.mozilla.org/mozilla-central
[task 2023-08-03T00:15:17.682Z] 00:15:17     INFO -  mozversion platform_version: 118.0a1
[task 2023-08-03T00:15:17.684Z] 00:15:17     INFO -  condprof INFO | environ({'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.wNmnDZ0nBY/Listeners', 'XPC_FLAGS': '0x0', 'MOZ_AUTOMATION': '1', 'MOZ_FETCHES_DIR': '/opt/worker/tasks/task_169102157889343/fetches', 'MOZ_FETCHES': '[{"artifact": "public/build/browsertime.tar.zst", "extract": true, "task": "TWXsc5gBSw60m1r_NpJXRw"}, {"artifact": "public/build/fix-stacks.tar.zst", "extract": true, "task": "VnM72U96Q9Kh8ojZuDeMiQ"}, {"artifact": "public/build/geckodriver.tar.gz", "extract": true, "task": "H92frk5qRZm1_R8PMImO2Q"}, {"artifact": "public/build/minidump-stackwalk.tar.zst", "extract": true, "task": "SB6UdryeR6O9aTXK4nuEpA"}, {"artifact": "public/build/node.tar.zst", "extract": true, "task": "NY4jp9PVRpCbX5r7UzDitQ"}, {"artifact": "public/ffmpeg-macos.zip", "extract": true, "task": "Hq6cJjZgR1uwvR2QPz0T8Q"}]', 'XPC_SERVICE_NAME': '0', 'MOZ_SCM_LEVEL': '3', 'LANG': 'en_US.UTF-8', 'TMPDIR': '/var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/', 'LOGNAME': 'cltbld', 'SCCACHE_DISABLE': '1', 'GECKO_HEAD_REV': '4e8d25555f9d9253daae12f37e70b494fe6bc018', 'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com', 'PYTHON': '/usr/local/bin/python3', 'SHELL': '/bin/bash', '_': '/usr/local/bin/start-worker', 'PWD': '/opt/worker', 'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/mozilla-central', 'MOZ_NODE_PATH': '/usr/local/bin/node', 'TASK_ID': 'd8hcSH-YRWmkdNu1f891yQ', 'SHLVL': '1', 'USER': 'cltbld', 'HOME': '/Users/cltbld', 'RUN_ID': '0', 'PATH': '/opt/worker/tasks/task_169102157889343/build/venv/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin', 'LC_ALL': 'en_US.UTF-8', 'EXTRA_MOZHARNESS_CONFIG': '{"installer_url": "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/coi7-0LhQj-pcCHZxX7Feg/artifacts/public/build/target.dmg", "test_packages_url": "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/coi7-0LhQj-pcCHZxX7Feg/artifacts/public/build/target.test_packages.json"}', 'TASKCLUSTER_PROXY_URL': 'http://localhost:8080', '__CF_USER_TEXT_ENCODING': '0x24:0x0:0x0', 'REQUIRE_GPU': '0', 'VIRTUAL_ENV': 'venv', 'MOZ_UPLOAD_DIR': '/opt/worker/tasks/task_169102157889343/build/blobber_upload_dir', 'MINIDUMP_STACKWALK': '/opt/worker/tasks/task_169102157889343/fetches/minidump-stackwalk/minidump-stackwalk', 'MINIDUMP_SAVE_PATH': '/opt/worker/tasks/task_169102157889343/build/blobber_upload_dir', 'RUST_BACKTRACE': 'full', 'PYTHONPATH': '/opt/worker/tasks/task_169102157889343/build/tests/raptor', 'SCRIPTSPATH': '/opt/worker/tasks/task_169102157889343/mozharness', 'EXTERNALTOOLSPATH': '/opt/worker/tasks/task_169102157889343/mozharness/external_tools'})
[task 2023-08-03T00:15:17.684Z] 00:15:17     INFO -  condprof INFO | Building settled x default
[task 2023-08-03T00:15:17.685Z] 00:15:17     INFO -  condprof INFO | Creating a fresh profile
[task 2023-08-03T00:15:17.685Z] 00:15:17     INFO -  condprof INFO | Setting prefs dict_items([('gfx.webrender.precache-shaders', True), ('focusmanager.testmode', True), ('marionette.defaultPrefs.port', 2828), ('marionette.port', 2828), ('remote.log.level', 'Trace'), ('marionette.log.truncate', False), ('extensions.autoDisableScopes', 10), ('devtools.debugger.remote-enabled', True), ('devtools.console.stdout.content', True), ('devtools.console.stdout.chrome', True)])
[task 2023-08-03T00:15:17.685Z] 00:15:17     INFO -  condprof INFO | Installing addons
[task 2023-08-03T00:15:17.685Z] 00:15:17     INFO -  condprof INFO | Updating profile located at '/var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpvz1gnl9q/profile'
[task 2023-08-03T00:15:17.686Z] 00:15:17     INFO -  condprof INFO | Reading existing metadata at /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpvz1gnl9q/profile/condprofile.json
[task 2023-08-03T00:15:17.686Z] 00:15:17     INFO -  condprof INFO | Could not find the metadata file in that profile
[task 2023-08-03T00:15:17.686Z] 00:15:17     INFO -  condprof INFO | Starting the Gecko app...
[task 2023-08-03T00:15:17.686Z] 00:15:17     INFO -  condprof INFO | Writing geckodriver logs in /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpmakgv82h/geckodriver-settled-default.log
[task 2023-08-03T00:15:17.690Z] 00:15:17     INFO -  condprof INFO | Running Webdriver on port 49270
[task 2023-08-03T00:15:17.690Z] 00:15:17     INFO -  condprof INFO | Running Marionette on port 2828
[task 2023-08-03T00:15:17.698Z] 00:15:17     INFO -  condprof INFO | url='http://localhost:49270/session' method='POST' body='{"desiredCapabilities": {"browserName": "firefox", "marionette": true, "acceptInsecureCerts": true, "moz:firefoxOptions": {"args": ["--allow-downgrade", "-profile", "/var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpvz1gnl9q/profile"], "binary": "/opt/worker/tasks/task_169102157889343/build/application/Firefox Nightly.app/Contents/MacOS/firefox", "prefs": {"focusmanager.testmode": true, "marionette.defaultPrefs.port": 2828, "marionette.port": 2828, "remote.log.level": "Trace", "marionette.log.truncate": false, "extensions.autoDisableScopes": 10, "devtools.debugger.remote-enabled": true, "devtools.console.stdout.content": true, "devtools.console.stdout.chrome": true}, "log": {"level": "trace"}}}}' headers={'Content-Type': 'application/json'} event='request'
[task 2023-08-03T00:15:20.008Z] 00:15:20     INFO -  condprof INFO | url='http://localhost:49270/session' method='POST' body='{"desiredCapabilities": {"browserName": "firefox", "marionette": true, "acceptInsecureCerts": true, "moz:firefoxOptions": {"args": ["--allow-downgrade", "-profile", "/var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpvz1gnl9q/profile"], "binary": "/opt/worker/tasks/task_169102157889343/build/application/Firefox Nightly.app/Contents/MacOS/firefox", "prefs": {"focusmanager.testmode": true, "marionette.defaultPrefs.port": 2828, "marionette.port": 2828, "remote.log.level": "Trace", "marionette.log.truncate": false, "extensions.autoDisableScopes": 10, "devtools.debugger.remote-enabled": true, "devtools.console.stdout.content": true, "devtools.console.stdout.chrome": true}, "log": {"level": "trace"}}}}' response=<ClientResponse(http://localhost:49270/session) [200 OK]>
[task 2023-08-03T00:15:20.008Z] 00:15:20     INFO -  <CIMultiDictProxy('Content-Type': 'application/json; charset=utf-8', 'Cache-Control': 'no-cache', 'Content-Length': '728', 'Date': 'Thu, 03 Aug 2023 00:15:17 GMT')>
[task 2023-08-03T00:15:20.009Z] 00:15:20     INFO -   data={'value': {'sessionId': '421d9556-6c3e-4f5b-862a-684f20a8cf9b', 'capabilities': {'acceptInsecureCerts': True, 'browserName': 'firefox', 'browserVersion': '118.0a1', 'marionette': True, 'moz:accessibilityChecks': False, 'moz:buildID': '20230802220030', 'moz:geckodriverVersion': '0.33.0', 'moz:headless': False, 'moz:platformVersion': '19.6.0', 'moz:processID': 1028, 'moz:profile': '/var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpvz1gnl9q/profile', 'moz:shutdownTimeout': 60000, 'moz:webdriverClick': True, 'moz:windowless': False, 'pageLoadStrategy': 'normal', 'platformName': 'mac', 'proxy': {}, 'setWindowRect': True, 'strictFileInteractability': False, 'timeouts': {'implicit': 0, 'pageLoad': 300000, 'script': 30000}, 'unhandledPromptBehavior': 'dismiss and notify'}}} event='response'
[task 2023-08-03T00:15:20.009Z] 00:15:20     INFO -  condprof INFO | Running the settled scenario
[task 2023-08-03T00:15:50.071Z] 00:15:50     INFO -  condprof INFO | settled scenario done.
[task 2023-08-03T00:15:50.071Z] 00:15:50     INFO -  condprof INFO | Closing all tabs
[task 2023-08-03T00:15:50.072Z] 00:15:50     INFO -  condprof INFO | url='http://localhost:49270/session/421d9556-6c3e-4f5b-862a-684f20a8cf9b/window/handles' method='GET' body=None headers={} event='request'
[task 2023-08-03T00:15:50.076Z] 00:15:50     INFO -  condprof INFO | url='http://localhost:49270/session/421d9556-6c3e-4f5b-862a-684f20a8cf9b/window/handles' method='GET' body=None response=<ClientResponse(http://localhost:49270/session/421d9556-6c3e-4f5b-862a-684f20a8cf9b/window/handles) [200 OK]>
[task 2023-08-03T00:15:50.077Z] 00:15:50     INFO -  <CIMultiDictProxy('Content-Type': 'application/json; charset=utf-8', 'Cache-Control': 'no-cache', 'Content-Length': '50', 'Date': 'Thu, 03 Aug 2023 00:15:49 GMT')>
[task 2023-08-03T00:15:50.077Z] 00:15:50     INFO -   data={'value': ['b86d5813-6414-428c-92be-7ed0cea723bf']} event='response'
[task 2023-08-03T00:15:50.077Z] 00:15:50     INFO -  condprof INFO | url='http://localhost:49270/session/421d9556-6c3e-4f5b-862a-684f20a8cf9b' method='DELETE' body=None headers={} event='request'
[task 2023-08-03T00:15:50.624Z] 00:15:50     INFO -  condprof INFO | url='http://localhost:49270/session/421d9556-6c3e-4f5b-862a-684f20a8cf9b' method='DELETE' body=None response=<ClientResponse(http://localhost:49270/session/421d9556-6c3e-4f5b-862a-684f20a8cf9b) [200 OK]>
[task 2023-08-03T00:15:50.624Z] 00:15:50     INFO -  <CIMultiDictProxy('Content-Type': 'application/json; charset=utf-8', 'Cache-Control': 'no-cache', 'Content-Length': '14', 'Date': 'Thu, 03 Aug 2023 00:15:49 GMT')>
[task 2023-08-03T00:15:50.624Z] 00:15:50     INFO -   data={'value': None} event='response'
[task 2023-08-03T00:15:50.707Z] 00:15:50     INFO -  condprof INFO | Creating metadata...
[task 2023-08-03T00:15:50.710Z] 00:15:50     INFO -  condprof INFO | Saving metadata file in /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpvz1gnl9q/profile/condprofile.json
[task 2023-08-03T00:15:50.710Z] 00:15:50     INFO -  condprof INFO | Profile at /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpvz1gnl9q/profile.
[task 2023-08-03T00:15:50.710Z] 00:15:50     INFO -  Done.
<...>
[task 2023-08-03T00:58:24.138Z] 00:58:24     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2023-08-03T00:58:28.641Z] 00:58:28     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[taskcluster:error] Aborting task...
[taskcluster:warn 2023-08-03T00:58:31.890Z] no such process
[taskcluster 2023-08-03T00:58:31.891Z] === Task Finished ===
[taskcluster 2023-08-03T00:58:31.891Z] Task Duration: 45m0.079689s
[taskcluster 2023-08-03T00:58:31.953Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-10-31T22:06:02.507Z
[taskcluster 2023-08-03T00:58:32.259Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/d8hcSH-YRWmkdNu1f891yQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-10-31T22:06:02.507Z
[taskcluster:error] Task aborted - max run time exceeded

Comment 1

[Ryan VanderMeulen [:RyanVM]]

This seems to be affecting all Youtube btime jobs across all trees.

Comment 2

[Serban Stanca [:SerbanS]]

I think this is also related with Bug 1846699, Bug 1846657 and Bug 1846658 as a regression from Bug 1784880. We can follow this in this range of backfills and retriggers.

Comment 3

[Serban Stanca [:SerbanS]]

The above range confirms that this is a fallout from Bug 1784880.

Comment 4

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

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

Comment 5

[Thomas Wisniewski [:twisniewski]]

Yes, this should also be fixed by the fix in bug 1846699.

Comment 6

[Intermittent Failures Robot]

47 failures in 679 pushes (0.069 failures/push) were associated with this bug yesterday.

Repository breakdown:

• firefox-android: 19
• mozilla-central: 28

Platform and build breakdown:

• android-hw-a51-11-0-aarch64-shippable-qr: 19
  • opt: 19
• macosx1015-64-shippable-qr: 22
  • opt: 22
• linux1804-64-shippable-qr: 2
  • opt: 2
• windows10-64-shippable-qr: 2
  • opt: 2
• linux1804-64-clang-trunk-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1846891&startday=2023-08-02&endday=2023-08-02&tree=all