1912848 - Intermittent Halting on failure while running ['/opt/worker/tasks/task_172350796640391/build/venv/bin/mozinstall', '/opt/worker/tasks/task_172350796640391/installer.dmg', '--destination', '/opt/worker/tasks/task_172350796640391/build/application']

Status: RESOLVED INCOMPLETE

(Firefox Build System :: Task Configuration, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2024-08-13T00:37:18.216Z] 00:37:18     INFO -   wcwidth == 0.1.7
[task 2024-08-13T00:37:18.216Z] 00:37:18     INFO -   wheel == 0.43.0
[task 2024-08-13T00:37:18.216Z] 00:37:18     INFO -   wptserve == 4.0.2
[task 2024-08-13T00:37:18.216Z] 00:37:18     INFO - Running post-action listener: _resource_record_post_action
[task 2024-08-13T00:37:18.216Z] 00:37:18     INFO - Running post-action listener: _start_resource_monitoring
[task 2024-08-13T00:37:18.217Z] 00:37:18     INFO - Starting resource monitoring.
[task 2024-08-13T00:37:18.250Z] 00:37:18     INFO - [mozharness: 2024-08-13 00:37:18.250235Z] Finished create-virtualenv step (success)
[task 2024-08-13T00:37:18.250Z] 00:37:18     INFO - [mozharness: 2024-08-13 00:37:18.250490Z] Running start-pulseaudio step.
[task 2024-08-13T00:37:18.250Z] 00:37:18     INFO - Running pre-action listener: _resource_record_pre_action
[task 2024-08-13T00:37:18.250Z] 00:37:18     INFO - Running main action method: start_pulseaudio
[task 2024-08-13T00:37:18.250Z] 00:37:18     INFO - Running post-action listener: _resource_record_post_action
[task 2024-08-13T00:37:18.251Z] 00:37:18     INFO - [mozharness: 2024-08-13 00:37:18.250996Z] Finished start-pulseaudio step (success)
[task 2024-08-13T00:37:18.251Z] 00:37:18     INFO - [mozharness: 2024-08-13 00:37:18.251063Z] Running install step.
[task 2024-08-13T00:37:18.251Z] 00:37:18     INFO - Running pre-action listener: _resource_record_pre_action
[task 2024-08-13T00:37:18.251Z] 00:37:18     INFO - Running main action method: install
[task 2024-08-13T00:37:18.251Z] 00:37:18     INFO - Getting output from command: ['/opt/worker/tasks/task_172350796640391/build/venv/bin/pip', 'list', '--format', 'freeze', '--no-index']
[task 2024-08-13T00:37:18.251Z] 00:37:18     INFO - Copy/paste: /opt/worker/tasks/task_172350796640391/build/venv/bin/pip list --format freeze --no-index
[task 2024-08-13T00:37:18.698Z] 00:37:18     INFO - Reading from file tmpfile_stdout
[task 2024-08-13T00:37:18.698Z] 00:37:18     INFO - Return code: 0
[task 2024-08-13T00:37:18.698Z] 00:37:18     INFO - mkdir: /opt/worker/tasks/task_172350796640391/build/application
[task 2024-08-13T00:37:18.699Z] 00:37:18     INFO - Getting output from command: ['/opt/worker/tasks/task_172350796640391/build/venv/bin/mozinstall', '/opt/worker/tasks/task_172350796640391/installer.dmg', '--destination', '/opt/worker/tasks/task_172350796640391/build/application']
[task 2024-08-13T00:37:18.699Z] 00:37:18     INFO - Copy/paste: /opt/worker/tasks/task_172350796640391/build/venv/bin/mozinstall /opt/worker/tasks/task_172350796640391/installer.dmg --destination /opt/worker/tasks/task_172350796640391/build/application
[task 2024-08-13T00:37:46.247Z] 00:37:46     INFO - Reading from file tmpfile_stderr
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR - Errors received:
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -  Traceback (most recent call last):
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -    File "/opt/worker/tasks/task_172350796640391/build/venv/lib/python3.11/site-packages/mozinstall/mozinstall.py", line 132, in install
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -      install_dir = _install_dmg(src, dest)
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -                    ^^^^^^^^^^^^^^^^^^^^^^^
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -    File "/opt/worker/tasks/task_172350796640391/build/venv/lib/python3.11/site-packages/mozinstall/mozinstall.py", line 334, in _install_dmg
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -      subprocess.check_call('hdiutil detach "%s" -quiet' % appDir, shell=True)
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -    File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/subprocess.py", line 413, in check_call
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -      raise CalledProcessError(retcode, cmd)
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -  subprocess.CalledProcessError: Command 'hdiutil detach "/Volumes/Firefox Nightly" -quiet' returned non-zero exit status 16.
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -  During handling of the above exception, another exception occurred:
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -  Traceback (most recent call last):
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -    File "/opt/worker/tasks/task_172350796640391/build/venv/bin/mozinstall", line 8, in <module>
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -      sys.exit(install_cli())
[task 2024-08-13T00:37:46.247Z] 00:37:46    ERROR -               ^^^^^^^^^^^^^
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -    File "/opt/worker/tasks/task_172350796640391/build/venv/lib/python3.11/site-packages/mozinstall/mozinstall.py", line 429, in install_cli
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -      install_path = install(src, options.dest)
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -                     ^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -    File "/opt/worker/tasks/task_172350796640391/build/venv/lib/python3.11/site-packages/mozinstall/mozinstall.py", line 157, in install
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -      reraise(InstallError, error, trbk)
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -    File "/opt/worker/tasks/task_172350796640391/build/venv/lib/python3.11/site-packages/six.py", line 695, in reraise
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -      raise value.with_traceback(tb)
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -    File "/opt/worker/tasks/task_172350796640391/build/venv/lib/python3.11/site-packages/mozinstall/mozinstall.py", line 132, in install
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -      install_dir = _install_dmg(src, dest)
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -                    ^^^^^^^^^^^^^^^^^^^^^^^
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -    File "/opt/worker/tasks/task_172350796640391/build/venv/lib/python3.11/site-packages/mozinstall/mozinstall.py", line 334, in _install_dmg
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -      subprocess.check_call('hdiutil detach "%s" -quiet' % appDir, shell=True)
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -    File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/subprocess.py", line 413, in check_call
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -      raise CalledProcessError(retcode, cmd)
[task 2024-08-13T00:37:46.248Z] 00:37:46    ERROR -  mozinstall.mozinstall.InstallError: Failed to install "/opt/worker/tasks/task_172350796640391/installer.dmg (Command 'hdiutil detach "/Volumes/Firefox Nightly" -quiet' returned non-zero exit status 16.)"
[task 2024-08-13T00:37:46.248Z] 00:37:46     INFO - Return code: 1
[task 2024-08-13T00:37:46.248Z] 00:37:46  WARNING - setting return code to 3
[task 2024-08-13T00:37:46.248Z] 00:37:46    FATAL - Halting on failure while running ['/opt/worker/tasks/task_172350796640391/build/venv/bin/mozinstall', '/opt/worker/tasks/task_172350796640391/installer.dmg', '--destination', '/opt/worker/tasks/task_172350796640391/build/application']
[task 2024-08-13T00:37:46.248Z] 00:37:46    FATAL - Running post_fatal callback...
[task 2024-08-13T00:37:46.248Z] 00:37:46    FATAL - Exiting 3
[task 2024-08-13T00:37:46.249Z] 00:37:46     INFO - Running post-action listener: _resource_record_post_action
[task 2024-08-13T00:37:46.249Z] 00:37:46     INFO - [mozharness: 2024-08-13 00:37:46.249069Z] Finished install step (failed)
[task 2024-08-13T00:37:46.249Z] 00:37:46     INFO - Running post-run listener: _resource_record_post_run
[task 2024-08-13T00:37:46.323Z] 00:37:46     INFO - instance_metadata.json not found; unable to determine instance type
[task 2024-08-13T00:37:46.324Z] 00:37:46     INFO - Validating Perfherder data against /opt/worker/tasks/task_172350796640391/mozharness/external_tools/performance-artifact-schema.json
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-remote.overall", "extraOptions": ["e10s", "buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 17.351991869918695}, {"name": "io_write_bytes", "value": 371646464}, {"name": "io.read_bytes", "value": 677124096}, {"name": "io_write_time", "value": 711}, {"name": "io_read_time", "value": 27977}]}, {"name": "mochitest.mochitest-remote.start-pulseaudio", "subtests": [{"name": "time", "value": 0.00035230900016358646}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-remote.install", "subtests": [{"name": "time", "value": 27.999458147999803}, {"name": "cpu_percent", "value": 17.351991869918695}]}]}
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - Total resource usage - Wall time: 28s; CPU: 17%; Read bytes: 677124096; Write bytes: 371646464; Read time: 27977; Write time: 711
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - TinderboxPrint: CPU usage<br/>17.4%
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - TinderboxPrint: I/O read bytes / time<br/>677,124,096 / 27,977
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - TinderboxPrint: I/O write bytes / time<br/>371,646,464 / 711
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - TinderboxPrint: CPU idle<br/>276.1 (82.7%)
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - TinderboxPrint: CPU system<br/>6.2 (1.9%)
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - TinderboxPrint: CPU user<br/>51.5 (15.4%)
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - TinderboxPrint: Swap in / out<br/>533,970,944 / 0
[task 2024-08-13T00:37:46.326Z] 00:37:46     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-08-13T00:37:46.328Z] 00:37:46     INFO - install - Wall time: 28s; CPU: 17%; Read bytes: 677124096; Write bytes: 371646464; Read time: 27977; Write time: 711
[taskcluster 2024-08-13T00:37:46.422Z]    Exit Code: 3
[taskcluster 2024-08-13T00:37:46.422Z]    User Time: 1m5.54992s
[taskcluster 2024-08-13T00:37:46.422Z]  Kernel Time: 19.911132s
[taskcluster 2024-08-13T00:37:46.422Z]    Wall Time: 5m4.560608s
[taskcluster 2024-08-13T00:37:46.422Z]       Result: FAILED
[taskcluster 2024-08-13T00:37:46.422Z] === Task Finished ===
[taskcluster 2024-08-13T00:37:46.422Z] Task Duration: 5m4.565162s
[taskcluster 2024-08-13T00:37:47.606Z] Uploading artifact public/logs/localconfig.json from file /opt/worker/tasks/task_172350796640391/logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2025-08-13T00:15:04.207Z
[taskcluster 2024-08-13T00:37:47.942Z] Uploading artifact public/test_info/profile_resource-usage.json from file /opt/worker/tasks/task_172350796640391/build/blobber_upload_dir/profile_resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2025-08-13T00:15:04.207Z
[taskcluster 2024-08-13T00:37:48.220Z] Uploading artifact public/test_info/resource-usage.json from file /opt/worker/tasks/task_172350796640391/build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2025-08-13T00:15:04.207Z
[taskcluster 2024-08-13T00:37:48.517Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2025-08-13T00:15:04.207Z
[taskcluster:error] exit status 3

Comment 1

[Intermittent Failures Robot]

1 failures in 2154 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1912848&startday=2024-08-12&endday=2024-08-18&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 3879 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 1

Platform and build breakdown:

• macosx1015-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1912848&startday=2024-08-26&endday=2024-09-01&tree=all

Comment 3

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.