Closed Bug 1849610 Opened 3 years ago Closed 2 years ago

Perma python-mozperftest [taskcluster:error] exit status 1

Categories

(Testing :: mozperftest, defect, P5)

Product:
Testing
Component:
mozperftest
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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

[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] popenargs = (['/Users/cltbld/.mozbuild/srcdirs/gecko-58f07ab5576f/_virtualenvs/common/bin/python', '-m', 'pip', 'install', 'mozperftest-tools==0.2.6'],)
[task 2023-08-21T15:06:13.974Z] kwargs = {}, retcode = 1
[task 2023-08-21T15:06:13.974Z] cmd = ['/Users/cltbld/.mozbuild/srcdirs/gecko-58f07ab5576f/_virtualenvs/common/bin/python', '-m', 'pip', 'install', 'mozperftest-tools==0.2.6']
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z]     def check_call(*popenargs, **kwargs):
[task 2023-08-21T15:06:13.974Z]         """Run command with arguments.  Wait for command to complete.  If
[task 2023-08-21T15:06:13.974Z]         the exit code was zero then return, otherwise raise
[task 2023-08-21T15:06:13.974Z]         CalledProcessError.  The CalledProcessError object will have the
[task 2023-08-21T15:06:13.974Z]         return code in the returncode attribute.
[task 2023-08-21T15:06:13.974Z]     
[task 2023-08-21T15:06:13.974Z]         The arguments are the same as for the call function.  Example:
[task 2023-08-21T15:06:13.974Z]     
[task 2023-08-21T15:06:13.974Z]         check_call(["ls", "-l"])
[task 2023-08-21T15:06:13.974Z]         """
[task 2023-08-21T15:06:13.974Z]         retcode = call(*popenargs, **kwargs)
[task 2023-08-21T15:06:13.974Z]         if retcode:
[task 2023-08-21T15:06:13.974Z]             cmd = kwargs.get("args")
[task 2023-08-21T15:06:13.974Z]             if cmd is None:
[task 2023-08-21T15:06:13.974Z]                 cmd = popenargs[0]
[task 2023-08-21T15:06:13.974Z] >           raise CalledProcessError(retcode, cmd)
[task 2023-08-21T15:06:13.974Z] E           subprocess.CalledProcessError: Command '['/Users/cltbld/.mozbuild/srcdirs/gecko-58f07ab5576f/_virtualenvs/common/bin/python', '-m', 'pip', 'install', 'mozperftest-tools==0.2.6']' returned non-zero exit status 1.
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] /Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/subprocess.py:363: CalledProcessError
[task 2023-08-21T15:06:13.974Z] ------------------------------ Captured log call -------------------------------
[task 2023-08-21T15:06:13.974Z] DEBUG    pip._internal.vcs.versioncontrol:versioncontrol.py:225 Registered VCS backend: bzr
[task 2023-08-21T15:06:13.974Z] DEBUG    pip._internal.vcs.versioncontrol:versioncontrol.py:225 Registered VCS backend: git
[task 2023-08-21T15:06:13.974Z] DEBUG    pip._internal.vcs.versioncontrol:versioncontrol.py:225 Registered VCS backend: hg
[task 2023-08-21T15:06:13.974Z] DEBUG    pip._internal.vcs.versioncontrol:versioncontrol.py:225 Registered VCS backend: svn
[task 2023-08-21T15:06:13.974Z] =============================== warnings summary ===============================
[task 2023-08-21T15:06:13.974Z] mozperftest/tests/test_mach_commands.py::test_fzf_flavor
[task 2023-08-21T15:06:13.974Z]   /opt/worker/tasks/task_169262955497255/checkouts/gecko/testing/mozbase/manifestparser/manifestparser/expression.py:213: DeprecationWarning: invalid escape sequence \w
[task 2023-08-21T15:06:13.974Z]     """
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] mozperftest/tests/test_runner.py: 620 warnings
[task 2023-08-21T15:06:13.974Z]   /opt/worker/tasks/task_169262955497255/checkouts/gecko/third_party/python/pip/pip/_vendor/packaging/version.py:114: DeprecationWarning: Creating a LegacyVersion has been deprecated and will be removed in the next major release
[task 2023-08-21T15:06:13.974Z]     DeprecationWarning,
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] -- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
[task 2023-08-21T15:06:13.974Z] ============================= slowest 10 durations =============================
[task 2023-08-21T15:06:13.974Z] 80.68s call     mozperftest/tests/test_runner.py::test_side_by_side
[task 2023-08-21T15:06:13.974Z] 3.20s call     mozperftest/tests/test_macos.py::test_mount_dmg
[task 2023-08-21T15:06:13.974Z] 0.72s call     mozperftest/tests/test_runner.py::test_main
[task 2023-08-21T15:06:13.974Z] 0.65s call     mozperftest/tests/test_notebookupload.py::test_compare_to_success[False]
[task 2023-08-21T15:06:13.974Z] 0.65s call     mozperftest/tests/test_notebookupload.py::test_compare_to_success[True]
[task 2023-08-21T15:06:13.974Z] 0.47s call     mozperftest/tests/test_perfherder.py::test_perfherder_validation_failure
[task 2023-08-21T15:06:13.974Z] 0.43s call     mozperftest/tests/test_perfherder.py::test_perfherder_with_alerting
[task 2023-08-21T15:06:13.974Z] 0.38s call     mozperftest/tests/test_perfherder.py::test_perfherder_simple_names
[task 2023-08-21T15:06:13.974Z] 0.37s call     mozperftest/tests/test_perfherder.py::test_perfherder_with_subunits
[task 2023-08-21T15:06:13.974Z] 0.37s call     mozperftest/tests/test_perfherder.py::test_perfherder_names_simplified_with_no_exclusions
[task 2023-08-21T15:06:13.974Z] =========================== short test summary info ============================
[task 2023-08-21T15:06:13.974Z] FAILED python/mozperftest/mozperftest/tests/test_runner.py::test_side_by_side
[task 2023-08-21T15:06:13.974Z] !!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!
[task 2023-08-21T15:06:13.974Z] ============ 1 failed, 153 passed, 621 warnings in 95.80s (0:01:35) ============
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] [FAILED]
[task 2023-08-21T15:06:13.974Z] Error running mach:
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z]     mach perftest-test
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] The error occurred in the implementation of the invoked mach command.
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] This should never occur and is likely a bug in the implementation of that
[task 2023-08-21T15:06:13.974Z] command.
[task 2023-08-21T15:06:13.974Z] You can invoke ``./mach busted`` to check if this issue is already on file. If it
[task 2023-08-21T15:06:13.974Z] isn't, please use ``./mach busted file perftest-test`` to report it. If ``./mach busted`` is
[task 2023-08-21T15:06:13.974Z] misbehaving, you can also inspect the dependencies of bug 1543241.
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] If filing a bug, please include the full output of mach, including this error
[task 2023-08-21T15:06:13.974Z] message.
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] The details of the failure are as follows:
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z] AssertionError
[task 2023-08-21T15:06:13.974Z] 
[task 2023-08-21T15:06:13.974Z]   File "/opt/worker/tasks/task_169262955497255/checkouts/gecko/python/mozperftest/mozperftest/mach_commands.py", line 198, in run_tests
[task 2023-08-21T15:06:13.975Z]     _run_tests(command_context, **kwargs)
[task 2023-08-21T15:06:13.975Z]   File "/opt/worker/tasks/task_169262955497255/checkouts/gecko/python/mozperftest/mozperftest/mach_commands.py", line 254, in _run_tests
[task 2023-08-21T15:06:13.975Z]     venv, "coverage", args, label="running tests", verbose=verbose
[taskcluster 2023-08-21T15:06:14.023Z]    Exit Code: 1
[taskcluster 2023-08-21T15:06:14.023Z]    User Time: 7m11.655193s
[taskcluster 2023-08-21T15:06:14.023Z]  Kernel Time: 7m33.215482s
[taskcluster 2023-08-21T15:06:14.023Z]    Wall Time: 5m6.149878s
[taskcluster 2023-08-21T15:06:14.023Z]       Result: FAILED
[taskcluster 2023-08-21T15:06:14.023Z] === Task Finished ===
[taskcluster 2023-08-21T15:06:14.023Z] Task Duration: 5m6.15454s
[taskcluster 2023-08-21T15:06:14.023Z] [mounts] Preserving cache: Moving "/opt/worker/tasks/task_169262955497255/checkouts" to "/opt/worker/cache/bRMRGtAWS5uc0asc18GJIg"
[taskcluster 2023-08-21T15:06:14.186Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LKnihQPHSBClWIITDV1zYQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-11-19T15:00:23.613Z
[taskcluster:error] exit status 1

Michelle, is it possible that your recent work on the mac machines pip something that broke pip install here?

Seems a bit farfetched, but I want to rule it out at least.

Also adding sparky, who I think owns this code?

Flags: needinfo?(mgoossens)
Flags: needinfo?(gmierz2)

I don't know if it's related or not, or perhaps masked this issue for awhile, but I noticed https://bugzilla.mozilla.org/show_bug.cgi?id=1849613 while looking into this.

I looked into some of the logs when I provisioned machines.
The only change python related is python3-psutil and python3-psutil 5.9.4 => 5.9.5

Flags: needinfo?(mgoossens)

I think this may be related to the opencv-python installation. For some reason, it's trying to build it from a tar instead of using the wheel:

[task 2023-08-23T08:04:30.641Z] python/mozperftest/mozperftest/tests/test_runner.py ..Collecting opencv-python==4.5.4.60
[task 2023-08-23T08:04:30.641Z]   Using cached opencv_python-4.5.4.60-cp38-cp38-macosx_10_15_x86_64.whl (45.9 MB)
[task 2023-08-23T08:04:30.641Z] Collecting numpy>=1.17.3
[task 2023-08-23T08:04:30.641Z]   Using cached numpy-1.24.4-cp38-cp38-macosx_10_9_x86_64.whl (19.8 MB)
[task 2023-08-23T08:04:30.641Z] Installing collected packages: numpy, opencv-python
[task 2023-08-23T08:04:30.641Z] Successfully installed numpy-1.24.4 opencv-python-4.5.4.60
[task 2023-08-23T08:04:30.641Z] Collecting mozperftest-tools==0.2.6
[task 2023-08-23T08:04:30.641Z]   Using cached mozperftest_tools-0.2.6-py3-none-any.whl (32 kB)
[task 2023-08-23T08:04:30.641Z] Collecting numpy
[task 2023-08-23T08:04:30.641Z]   Using cached numpy-1.24.4-cp38-cp38-macosx_10_9_x86_64.whl (19.8 MB)
[task 2023-08-23T08:04:30.641Z] Collecting scipy
[task 2023-08-23T08:04:30.641Z]   Using cached scipy-1.10.1-cp38-cp38-macosx_10_9_x86_64.whl (35.0 MB)
[task 2023-08-23T08:04:30.641Z] Collecting opencv-python
[task 2023-08-23T08:04:30.641Z]   Downloading opencv-python-4.8.0.76.tar.gz (92.1 MB)
[task 2023-08-23T08:04:30.641Z]      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 92.1/92.1 MB 24.1 MB/s eta 0:00:00

Has the python version used in CI changed, or anything related to how the wheels are fetched and installed?

Flags: needinfo?(gmierz2) → needinfo?(bhearsum)

(In reply to Greg Mierzwinski [:sparky] from comment #4)

I think this may be related to the opencv-python installation. For some reason, it's trying to build it from a tar instead of using the wheel:

[task 2023-08-23T08:04:30.641Z] python/mozperftest/mozperftest/tests/test_runner.py ..Collecting opencv-python==4.5.4.60
[task 2023-08-23T08:04:30.641Z]   Using cached opencv_python-4.5.4.60-cp38-cp38-macosx_10_15_x86_64.whl (45.9 MB)
[task 2023-08-23T08:04:30.641Z] Collecting numpy>=1.17.3
[task 2023-08-23T08:04:30.641Z]   Using cached numpy-1.24.4-cp38-cp38-macosx_10_9_x86_64.whl (19.8 MB)
[task 2023-08-23T08:04:30.641Z] Installing collected packages: numpy, opencv-python
[task 2023-08-23T08:04:30.641Z] Successfully installed numpy-1.24.4 opencv-python-4.5.4.60
[task 2023-08-23T08:04:30.641Z] Collecting mozperftest-tools==0.2.6
[task 2023-08-23T08:04:30.641Z]   Using cached mozperftest_tools-0.2.6-py3-none-any.whl (32 kB)
[task 2023-08-23T08:04:30.641Z] Collecting numpy
[task 2023-08-23T08:04:30.641Z]   Using cached numpy-1.24.4-cp38-cp38-macosx_10_9_x86_64.whl (19.8 MB)
[task 2023-08-23T08:04:30.641Z] Collecting scipy
[task 2023-08-23T08:04:30.641Z]   Using cached scipy-1.10.1-cp38-cp38-macosx_10_9_x86_64.whl (35.0 MB)
[task 2023-08-23T08:04:30.641Z] Collecting opencv-python
[task 2023-08-23T08:04:30.641Z]   Downloading opencv-python-4.8.0.76.tar.gz (92.1 MB)
[task 2023-08-23T08:04:30.641Z]      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 92.1/92.1 MB 24.1 MB/s eta 0:00:00

Has the python version used in CI changed, or anything related to how the wheels are fetched and installed?

Not that I'm aware of :(

Flags: needinfo?(bhearsum)

Ok, so something is triggering an install for opencv-python==4.8.0.76 which we don't have a wheel for. Note that we did already install opencv-python-4.5.4.60. Locally on linux, I'm able to run these in a venv without triggering the install of a newer opencv-python version. Will keep looking.

Flags: needinfo?(gmierz2)

I think this issue is coming from the unpinned dependencies here: https://github.com/mozilla/mozperftest-tools/blob/823f58ee1530fb4c488338fbbfe9acd1ce9b4aad/mozperftest_tools/setup.py#L14

I'm not entirely sure why we've only started hitting this failure now though.

Filed bug to upload new package here: bug 1850510

I managed to fix the error and prevent opencv-python 4.8 from being installed with an update to mozperftest-tools, but now there's a new failure: https://treeherder.mozilla.org/jobs?repo=try&revision=d1e6f0050c4a70ce5977e3f23026d7af54aae517

Flags: needinfo?(gmierz2)
Flags: needinfo?(gmierz2)
See Also: → 1850724

I have a feeling it's being caused by something in this function: https://searchfox.org/mozilla-central/source/python/mozperftest/mozperftest/utils.py#130-172

I've filed bug 1850763 to remove that method at some point because there's little reason for us to have a custom system for python package setup. That said, it's possible that we need to do it this way because we're not using mozharness in mozperftest, and are actively avoiding it.

I've managed to fix it in this try run: https://treeherder.mozilla.org/jobs?repo=try&revision=8330b94e182bf33756b451be6ae2ab8632df21ab

If you look at this patch, you'll see that I skipped installing the dependencies using --no-deps and installed them myself: https://hg.mozilla.org/try/rev/b11459a70161d9666eae96aab2d26996ef50fd68

:masterwayz, I see that :bhearsum mentioned something about pip/pip install, and I'm wondering if you can provide some more context about those changes? Also, the changes which could have broken this test span from August 9th to August 23rd. This is the last passing mozilla-central push: https://treeherder.mozilla.org/jobs?repo=mozilla-central&revision=46b5603cd2b8de629b659ec8d44fc7b086782c46

The function that's broken on our side is this install_package one which uses some pip internals: https://searchfox.org/mozilla-central/source/python/mozperftest/mozperftest/utils.py#130-172

Flags: needinfo?(gmierz2) → needinfo?(mgoossens)
See Also: → 1850817

This could've been changed during updates, which is unintentional.
I don't know how things are set up when it comes to pip.

Flags: needinfo?(mgoossens)
Group: core-security-release

I meant to make this confidential for mozilla employees, not sure how to get the bug into that state.

While debugging this bug, I was thinking about how opencv-python 4.8 was attempting to get installed onto our machines, and I realized that this shouldn't be possible or wasn't possible in the past. We would have had to upload the tar/wheels to here but I can't find any there: https://pypi.pub.build.mozilla.org/pub/

It seems like this might be a security issue since pip is now bypassing our internal mirror and checking an external one instead. :bhearsum, what do you think?

Flags: needinfo?(bhearsum)
Group: core-security-release → mozilla-employee-confidential

(In reply to Greg Mierzwinski [:sparky] from comment #15)

I meant to make this confidential for mozilla employees, not sure how to get the bug into that state.

While debugging this bug, I was thinking about how opencv-python 4.8 was attempting to get installed onto our machines, and I realized that this shouldn't be possible or wasn't possible in the past. We would have had to upload the tar/wheels to here but I can't find any there: https://pypi.pub.build.mozilla.org/pub/

It seems like this might be a security issue since pip is now bypassing our internal mirror and checking an external one instead. :bhearsum, what do you think?

I checked with our SRE team and it is expected that these machines can contact outside services. Obviously we'd like to avoid this for reproducability and clarity reasons, but we don't lock down outbound access for security purposes.

If I understand things correctly, this bypassed internal pypi because of the custom pip install work being done in this task. If that's the case, this boils down to a bug in the test script IMO.

Group: mozilla-employee-confidential
Flags: needinfo?(bhearsum)

Ok thanks for the information, but using this same method, this wasn't possible before this failure started, and it's unclear what change made it possible. Would you know what changed to make this possible?

Flags: needinfo?(bhearsum)

(In reply to Greg Mierzwinski [:sparky] from comment #17)

Ok thanks for the information, but using this same method, this wasn't possible before this failure started, and it's unclear what change made it possible. Would you know what changed to make this possible?

I spoke with our SREs about this. It turns out we used to have a pip.conf to help avoid this. https://mozilla-hub.atlassian.net/browse/RELOPS-708 tracks adding this back.

Flags: needinfo?(bhearsum)

That's great, thanks a lot for digging into this! Interesting how that only started causing issues now.

Yeah, very interesting.

We haven't fully reimaged many Macs since 2020 and recently did some. (MacStadium hosts are new and wouldn't have had a pip.conf though... but they only few types of tests.) If no new test types were run the dependencies would remain satisfied. Something like that is my theory, but definitely makes my head hurt. :)

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

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE

Reopened as it hasn't been resolved.

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE

It looks like this has been resolved now, here's a passing run for OSX on November 6th: https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=perftest&revision=cfad60e16bc9ffd1123a5eb881ba42aaa60b9b18

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.