Open Bug 1771825 Opened 3 years ago Updated 11 days ago

Intermittent Could not install python package: failed all attempts.

Categories

(Infrastructure & Operations :: RelOps: General, defect, P5)

Product:
Infrastructure & Operations
Component:
RelOps: General
Type:
defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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

[task 2022-05-30T23:49:52.111Z] 23:49:52  WARNING - Return code: 1
[task 2022-05-30T23:49:52.111Z] 23:49:52     INFO - retry: Failed, sleeping 300 seconds before retrying
[task 2022-05-30T23:54:52.243Z] 23:54:52     INFO - retry: Calling run_command with args: [['C:\\Users\\task_1653943727\\build\\venv\\Scripts\\pip', 'install', '--timeout', '120', '-r', 'C:\\Users\\task_1653943727\\build\\tests\\raptor\\requirements.txt', '--no-index', '--find-links', 'https://pypi.pub.build.mozilla.org/pub/']], kwargs: {'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': re.compile('\\d+: error: '), 'level': 'error'}, {'regex': re.compile('\\d+: warning: '), 'level': 'warning'}, {'regex': re.compile('Downloading .* \\(.*\\): *([0-9]+%)? *[0-9\\.]+[kmKM]b'), 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': re.compile('Warning:.*Error: '), 'level': 'warning'}, {'regex': re.compile('package.*> Error:'), 'level': 'error'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': re.compile('raise \\w*Exception: '), 'level': 'critical'}, {'regex': re.compile('raise \\w*Error: '), 'level': 'critical'}], 'cwd': 'C:\\Users\\task_1653943727\\build\\tests\\raptor', 'env': {'ALLUSERSPROFILE': 'C:\\ProgramData', 'APPDATA': 'C:\\Users\\task_1653943727\\AppData\\Roaming', 'COMMONPROGRAMFILES': 'C:\\Program Files\\Common Files', 'COMMONPROGRAMFILES(X86)': 'C:\\Program Files (x86)\\Common Files', 'COMMONPROGRAMW6432': 'C:\\Program Files\\Common Files', 'COMPUTERNAME': 'T-W1064-MS-040', 'COMSPEC': 'C:\\windows\\system32\\cmd.exe', 'DRIVERDATA': 'C:\\Windows\\System32\\Drivers\\DriverData', 'EXTRA_MOZHARNESS_CONFIG': '{"installer_url": "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Bl1VRWYKQRCaeS0ecL0fZQ/artifacts/public/build/target.zip", "test_packages_url": "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Bl1VRWYKQRCaeS0ecL0fZQ/artifacts/public/build/target.test_packages.json"}', 'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/mozilla-central', 'GECKO_HEAD_REV': 'f5c06f04952fc5d22644704c505a956834ed65c5', 'HG_CACHE': 'C:\\tooltool-cache', 'HOMEDRIVE': 'C:', 'HOMEPATH': '\\Users\\task_1653943727', 'LOCALAPPDATA': 'C:\\Users\\task_1653943727\\AppData\\Local', 'LOGONSERVER': '\\\\T-W1064-MS-040', 'MOZILLABUILD': 'C:\\mozilla-build', 'MOZ_AUTOMATION': '1', 'MOZ_FETCHES': '[{"artifact": "public/assorted-dom-54c3c3d9d3f6.zip", "extract": true, "task": "D8kFkO49Ta2V5OqJp0IQNA"}, {"artifact": "public/build/browsertime.tar.zst", "extract": true, "task": "PdpLFJmsS7aMEHk0pRVKng"}, {"artifact": "public/build/fix-stacks.tar.zst", "extract": true, "task": "ZZM3FixpR6OwfGrMKYrqYw"}, {"artifact": "public/build/geckodriver.zip", "extract": true, "task": "CvZbzNemSeGeCyQXX4mkUQ"}, {"artifact": "public/build/minidump-stackwalk.tar.zst", "extract": true, "task": "QLXmpAWbQ3Gi7qENMCQ9iQ"}, {"artifact": "public/build/node.tar.zst", "extract": true, "task": "AIVaaOjPRhCQU1YT1w--Bg"}, {"artifact": "public/ffmpeg-4.1.1-win64-static.zip", "extract": true, "task": "L8nL3vswT66Lh3rtTCwiMg"}, {"artifact": "public/jetstream2-54c3c3d9d3f6.zip", "extract": true, "task": "ZxSUALQlRBCrZM7YryeG6Q"}, {"artifact": "public/matrix-react-bench-c51ca3fc73cd.zip", "extract": true, "task": "Dx6qbvdNT66Jyl6sJJGEIw"}, {"artifact": "public/unity-webgl-54c3c3d9d3f6.zip", "extract": true, "task": "UBuzyT_IRRqzc6Ygjd8Tcw"}]', 'MOZ_FETCHES_DIR': 'C:/Users/task_1653943727/fetches', 'MOZ_SCM_LEVEL': '3', 'NUMBER_OF_PROCESSORS': '8', 'ONEDRIVE': 'C:\\Users\\task_1653943727\\OneDrive', 'OS': 'Windows_NT', 'PATH': 'C:\\windows\\system32;C:\\windows;C:\\windows\\System32\\Wbem;C:\\windows\\System32\\WindowsPowerShell\\v1.0\\;C:\\windows\\System32\\OpenSSH\\;C:\\Program Files\\Puppet Labs\\Puppet\\bin;C:\\Program Files\\Mellanox\\MLNX_VPI\\IB\\Tools;C:\\Program Files\\Mellanox\\MLNX_CIMProvider\\lib\\mft;C:\\Program Files\\Git\\cmd;C:\\Program Files (x86)\\GNU\\GnuPG\\pub;C:\\Program Files\\Mercurial\\;C:\\Program Files\\Mercurial;C:\\mozilla-build\\bin;C:\\mozilla-build\\kdiff;C:\\mozilla-build\\moztools-x64\\bin;C:\\mozilla-build\\mozmake;C:\\mozilla-build\\nsis-3.01;C:\\mozilla-build\\python;C:\\mozilla-build\\python\\Scripts;C:\\mozilla-build\\python3;C:\\mozilla-build\\msys\\bin;C:\\mozilla-build\\msys\\local\\bin;C:\\Program Files (x86)\\Windows Kits\\10\\Windows Performance Toolkit\\;C:\\Users\\task_1653943727\\AppData\\Local\\Microsoft\\WindowsApps;c:\\slave\\test\\build\\application\\firefox;', 'PATHEXT': '.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC', 'PIP_DOWNLOAD_CACHE': 'C:\\pip-cache', 'PROCESSOR_ARCHITECTURE': 'AMD64', 'PROCESSOR_IDENTIFIER': 'Intel64 Family 6 Model 94 Stepping 3, GenuineIntel', 'PROCESSOR_LEVEL': '6', 'PROCESSOR_REVISION': '5e03', 'PROGRAMDATA': 'C:\\ProgramData', 'PROGRAMFILES': 'C:\\Program Files', 'PROGRAMFILES(X86)': 'C:\\Program Files (x86)', 'PROGRAMW6432': 'C:\\Program Files', 'PROMPT': '$P$G', 'PSMODULEPATH': '%ProgramFiles%\\WindowsPowerShell\\Modules;C:\\windows\\system32\\WindowsPowerShell\\v1.0\\Modules;C:\\Program Files\\Mellanox\\MLNX_VPI\\Tools\\WMI\\Modules;C:\\Program Files\\Mellanox\\MLNX_CIMProvider\\WMI\\Modules', 'PUBLIC': 'C:\\Users\\Public', 'PYTHON': 'c:\\mozilla-build\\python3\\python3.exe', 'SCCACHE_DISABLE': '1', 'SYSTEMDRIVE': 'C:', 'SYSTEMROOT': 'C:\\windows', 'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com', 'TASK_ID': 'UCizBjh-R16wXyT73jfItA', 'TASK_STOP_TIME': '1653953447', 'TASKCLUSTER_PROXY_URL': 'http://localhost:80', 'TEMP': 'C:\\Users\\task_1653943727\\AppData\\Local\\Temp', 'TMP': 'C:\\Users\\task_1653943727\\AppData\\Local\\Temp', 'TOOLTOOL_CACHE': 'C:\\builds\\tooltool_cache', 'USERDOMAIN': 'T-W1064-MS-040', 'USERDOMAIN_ROAMINGPROFILE': 'T-W1064-MS-040', 'USERNAME': 'task_1653943727', 'USERPROFILE': 'C:\\Users\\task_1653943727', 'WINDIR': 'C:\\windows'}, 'error_level': 'warning'}, attempt #5
[task 2022-05-30T23:54:52.243Z] 23:54:52     INFO - Running command: ['C:\\Users\\task_1653943727\\build\\venv\\Scripts\\pip', 'install', '--timeout', '120', '-r', 'C:\\Users\\task_1653943727\\build\\tests\\raptor\\requirements.txt', '--no-index', '--find-links', 'https://pypi.pub.build.mozilla.org/pub/'] in C:\Users\task_1653943727\build\tests\raptor
[task 2022-05-30T23:54:52.243Z] 23:54:52     INFO - Copy/paste: C:\Users\task_1653943727\build\venv\Scripts\pip install --timeout 120 -r C:\Users\task_1653943727\build\tests\raptor\requirements.txt --no-index --find-links https://pypi.pub.build.mozilla.org/pub/
[task 2022-05-30T23:54:52.243Z] 23:54:52     INFO - Using env: (same as previous command)
[task 2022-05-30T23:54:52.702Z] 23:54:52     INFO -  Looking in links: https://pypi.pub.build.mozilla.org/pub/
[task 2022-05-30T23:54:52.703Z] 23:54:52     INFO -  Processing c:\users\task_1653943727\build\tests\condprofile
[task 2022-05-30T23:54:52.704Z] 23:54:52     INFO -    DEPRECATION: A future pip version will change local packages to be built in-place without first copying to a temporary directory. We recommend you use --use-feature=in-tree-build to test your packages with this new behavior before it becomes the default.
[task 2022-05-30T23:54:52.705Z] 23:54:52     INFO -     pip 21.3 will remove support for this functionality. You can find discussion regarding this at https://github.com/pypa/pip/issues/7555.
[task 2022-05-30T23:54:53.458Z] 23:54:53     INFO -  Collecting arsenic==19.1
[task 2022-05-30T23:54:53.643Z] 23:54:53     INFO -    Using cached https://pypi.pub.build.mozilla.org/pub/arsenic-19.1-py3-none-any.whl (18 kB)
[task 2022-05-30T23:54:54.300Z] 23:54:54     INFO -  Collecting mozcrash~=2.0
[task 2022-05-30T23:54:54.310Z] 23:54:54     INFO -    Using cached https://pypi.pub.build.mozilla.org/pub/mozcrash-2.1.0.tar.gz (9.2 kB)
[task 2022-05-30T23:54:54.619Z] 23:54:54     INFO -  Collecting mozrunner~=7.0
[task 2022-05-30T23:54:54.630Z] 23:54:54     INFO -    Using cached https://pypi.pub.build.mozilla.org/pub/mozrunner-7.7.0-py2.py3-none-any.whl (34 kB)
[task 2022-05-30T23:54:54.634Z] 23:54:54     INFO -  Requirement already satisfied: mozprofile~=2.1 in c:\users\task_1653943727\build\venv\lib\site-packages (from -r C:\Users\task_1653943727\build\tests\raptor\requirements.txt (line 3)) (2.5.0)
[task 2022-05-30T23:54:54.669Z] 23:54:54     INFO -  Collecting manifestparser>=1.1
[task 2022-05-30T23:54:54.680Z] 23:54:54     INFO -    Using cached https://pypi.pub.build.mozilla.org/pub/manifestparser-1.1.tar.gz (16 kB)
[task 2022-05-30T23:54:54.988Z] 23:54:54     INFO -  Collecting wptserve~=3.0
[task 2022-05-30T23:54:54.999Z] 23:54:54     INFO -    Using cached https://pypi.pub.build.mozilla.org/pub/wptserve-3.0.tar.gz (44 kB)
[task 2022-05-30T23:54:55.330Z] 23:54:55     INFO -  ERROR: Could not find a version that satisfies the requirement mozdevice>=4.0.0 (from versions: 0.2, 0.9, 0.12, 0.15, 0.18, 0.19, 0.21, 0.22, 0.26, 0.40, 0.44, 0.46, 0.48, 3.0.4, 3.0.5, 3.0.6)
[task 2022-05-30T23:54:55.330Z] 23:54:55     INFO -  ERROR: No matching distribution found for mozdevice>=4.0.0
[task 2022-05-30T23:54:55.513Z] 23:54:55  WARNING - Return code: 1
[task 2022-05-30T23:54:55.513Z] 23:54:55    FATAL - Could not install python package: failed all attempts.
[task 2022-05-30T23:54:55.513Z] 23:54:55    FATAL - Running post_fatal callback...
[task 2022-05-30T23:54:55.513Z] 23:54:55    FATAL - Exiting -1
[task 2022-05-30T23:54:55.513Z] 23:54:55     INFO - Running post-action listener: _resource_record_post_action
[task 2022-05-30T23:54:55.513Z] 23:54:55     INFO - Running post-action listener: _start_resource_monitoring
[task 2022-05-30T23:54:55.539Z] 23:54:55     INFO - Starting resource monitoring.
[task 2022-05-30T23:54:55.546Z] 23:54:55     INFO - [mozharness: 2022-05-30 23:54:55.546080Z] Finished create-virtualenv step (failed)
[task 2022-05-30T23:54:55.546Z] 23:54:55     INFO - Running post-run listener: _resource_record_post_run
[taskcluster 2022-05-30T23:54:55.840Z]    Exit Code: 4294967295
[taskcluster 2022-05-30T23:54:55.840Z]    User Time: 0s
[taskcluster 2022-05-30T23:54:55.840Z]  Kernel Time: 0s
[taskcluster 2022-05-30T23:54:55.840Z]    Wall Time: 14m3.0990013s
[taskcluster 2022-05-30T23:54:55.840Z]       Result: FAILED
[taskcluster 2022-05-30T23:54:55.840Z] === Task Finished ===
[taskcluster 2022-05-30T23:54:55.840Z] Task Duration: 14m3.0990013s
[taskcluster 2022-05-30T23:54:55.925Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2023-05-30T22:03:48.203Z
[taskcluster 2022-05-30T23:54:56.143Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2023-05-30T22:03:48.203Z
[taskcluster 2022-05-30T23:54:56.299Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UCizBjh-R16wXyT73jfItA/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-05-30T22:03:48.203Z
[taskcluster:error] exit status 4294967295

Only one failure recently on windows (windows10-64-shippable-qr).

Summary: Intermittent [Tier 2] Could not install python package: failed all attempts. → Intermittent Could not install python package: failed all attempts.

Most failures here (if not all) have ModuleNotFoundError: No module named 'mozsystemmonitor'.
Dave, is this something you can look into? Thank you.

Flags: needinfo?(dhouse)

Mark, this looks like some python failures on moonshots and acers?

[task 2022-10-18T19:36:27.958Z] 19:36:27     INFO - Using env: (same as previous command)
[task 2022-10-18T19:36:28.135Z] 19:36:28     INFO -  No Python at 'c:\mozilla-build\python3\python.exe'
[task 2022-10-18T19:36:28.138Z] 19:36:28  WARNING - Return code: 103
[task 2022-10-18T19:36:28.138Z] 19:36:28    FATAL - Could not install python package: failed all attempts.
[task 2022-10-18T19:36:28.138Z] 19:36:28    FATAL - Running post_fatal callback...
[task 2022-10-18T19:36:28.138Z] 19:36:28    FATAL - Exiting -1
[task 2022-10-18T19:36:28.138Z] 19:36:28     INFO - Running post-action listener: _resource_record_post_action
[task 2022-10-18T19:36:28.138Z] 19:36:28     INFO - Running post-action listener: _start_resource_monitoring
[task 2022-10-18T19:36:28.216Z] 19:36:28  WARNING - Unable to start resource monitor: Traceback (most recent call last):
[task 2022-10-18T19:36:28.216Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\base\script.py", line 2293, in run_action
[task 2022-10-18T19:36:28.216Z] 19:36:28  WARNING -     self._possibly_run_method(method_name, error_if_missing=True)
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\base\script.py", line 2245, in _possibly_run_method
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -     return getattr(self, method_name)()
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\mozilla\testing\talos.py", line 745, in create_virtualenv
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -     super(Talos, self).create_virtualenv()
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\base\python.py", line 593, in create_virtualenv
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -     self.install_module(
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\base\python.py", line 390, in install_module
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -     self.retry(
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\base\script.py", line 1287, in retry
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -     self.log(
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\base\log.py", line 126, in log
[task 2022-10-18T19:36:28.217Z] 19:36:28  WARNING -     return self.log_obj.log_message(
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\base\log.py", line 617, in log_message
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING -     raise SystemExit(exit_code)
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING - SystemExit: -1
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING - 
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING - During handling of the above exception, another exception occurred:
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING - 
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING - Traceback (most recent call last):
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING -   File "C:\Users\task_1666114133\mozharness\mozharness\base\python.py", line 694, in _start_resource_monitoring
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING -     from mozsystemmonitor.resourcemonitor import SystemResourceMonitor
[task 2022-10-18T19:36:28.218Z] 19:36:28  WARNING - ModuleNotFoundError: No module named 'mozsystemmonitor'
[task 2022-10-18T19:36:28.218Z] 19:36:28     INFO - [mozharness: 2022-10-18 19:36:28.218344Z] Finished create-virtualenv step (failed)
[task 2022-10-18T19:36:28.218Z] 19:36:28     INFO - Running post-run listener: _resource_record_post_run
Flags: needinfo?(dhouse) → needinfo?(mcornmesser)

(In reply to :dhouse from comment #19)

Mark, this looks like some python failures on moonshots and acers?

It does, and scrolling back up it looks like the uptick was right around the time Python was reverted this passed weekend.

CosminS, Are these test now perma failing or is it intermittent?

Flags: needinfo?(mcornmesser) → needinfo?(csabou)
Flags: needinfo?(mcornmesser)

CosminS, Are these test now perma failing or is it intermittent?

Looking and these windows10-64-ref-hw-2017-qr talos ones, one can say they're permafailing.

The browsertime ones are not permafailing but they do have quite a high frequency failure rate that is observed also in https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2022-10-12&endday=2022-10-19&tree=trunk&bug=1771825

Flags: needinfo?(csabou)

Yeah I think this is related to reverting Python which happen on Saturday. I will start looking at updating and troubleshooting Python on these workers starting tomorrow.

Flags: needinfo?(mcornmesser)

Just an update. I am still hashing out the Python upgrade in a way it doesn't break the automated restore function. I am hoping to have a fix early next week.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended]
See Also: → 1879665

The recent spike here might be related to issues in Bug 1886662.

this recent spike is fixed; There was a psutil 5.9.8 available as a tar.gz and that was being used instead of the 5.9.3.whl version.

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