1761150 - Perma [tier2] package> mozmake[5]: *** [Z:/task_164807469337731/build/src/toolkit/mozapps/installer/packager.mk:34: stage-package] Error 1 | PermissionError: [WinError 5] Access is denied

Status: RESOLVED FIXED

(Firefox Build System :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-03-23T23:48:33.686Z] 23:48:33     INFO -  package> WARNING: Found 26 duplicated files taking 81550 bytes (uncompressed)
[task 2022-03-23T23:48:33.686Z] 23:48:33     INFO -  package> # Package mozharness
[task 2022-03-23T23:48:33.687Z] 23:48:33     INFO -  package> z:/task_164807469337731/workspace/obj-build/_virtualenvs/build/Scripts/python.exe -m mozbuild.action.test_archive  mozharness z:/task_164807469337731/workspace/obj-build/dist/mozharness.zip
[task 2022-03-23T23:48:33.687Z] 23:48:33     INFO -  package> Wrote 706 files in 9533566 bytes to mozharness.zip in 1.55s
[task 2022-03-23T23:48:33.688Z] 23:48:33     INFO -  package> # Package JavaScript Shell
[task 2022-03-23T23:48:33.688Z] 23:48:33     INFO -  package> Packaging JavaScript Shell...
[task 2022-03-23T23:48:33.688Z] 23:48:33     INFO -  package> rm -f ../../dist/target.jsshell.zip
[task 2022-03-23T23:48:33.690Z] 23:48:33     INFO -  package> z:/task_164807469337731/workspace/obj-build/_virtualenvs/build/Scripts/python.exe -m mozbuild.action.zip -C ../../dist/bin --strip z:/task_164807469337731/workspace/obj-build/dist/target.jsshell.zip js.exe mozglue.dll  nss3.dll vcruntime140.dll msvcp140.dll api-ms-win-core-file-l1-2-0.dll api-ms-win-core-file-l2-1-0.dll api-ms-win-core-localization-l1-2-0.dll api-ms-win-core-processthreads-l1-1-1.dll api-ms-win-core-synch-l1-2-0.dll api-ms-win-core-timezone-l1-1-0.dll api-ms-win-crt-conio-l1-1-0.dll api-ms-win-crt-convert-l1-1-0.dll api-ms-win-crt-environment-l1-1-0.dll api-ms-win-crt-filesystem-l1-1-0.dll api-ms-win-crt-heap-l1-1-0.dll api-ms-win-crt-locale-l1-1-0.dll api-ms-win-crt-math-l1-1-0.dll api-ms-win-crt-multibyte-l1-1-0.dll api-ms-win-crt-private-l1-1-0.dll api-ms-win-crt-process-l1-1-0.dll api-ms-win-crt-runtime-l1-1-0.dll api-ms-win-crt-stdio-l1-1-0.dll api-ms-win-crt-string-l1-1-0.dll api-ms-win-crt-time-l1-1-0.dll api-ms-win-crt-utility-l1-1-0.dll ucrtbase.dll
[task 2022-03-23T23:48:33.691Z] 23:48:33     INFO -  package> BUILDTASK {"argv": ["z:\\task_164807469337731\\build\\src\\python\\mozbuild\\mozbuild\\action\\zip.py", "-C", "../../dist/bin", "--strip", "z:/task_164807469337731/workspace/obj-build/dist/target.jsshell.zip", "js.exe", "mozglue.dll", "nss3.dll", "vcruntime140.dll", "msvcp140.dll", "api-ms-win-core-file-l1-2-0.dll", "api-ms-win-core-file-l2-1-0.dll", "api-ms-win-core-localization-l1-2-0.dll", "api-ms-win-core-processthreads-l1-1-1.dll", "api-ms-win-core-synch-l1-2-0.dll", "api-ms-win-core-timezone-l1-1-0.dll", "api-ms-win-crt-conio-l1-1-0.dll", "api-ms-win-crt-convert-l1-1-0.dll", "api-ms-win-crt-environment-l1-1-0.dll", "api-ms-win-crt-filesystem-l1-1-0.dll", "api-ms-win-crt-heap-l1-1-0.dll", "api-ms-win-crt-locale-l1-1-0.dll", "api-ms-win-crt-math-l1-1-0.dll", "api-ms-win-crt-multibyte-l1-1-0.dll", "api-ms-win-crt-private-l1-1-0.dll", "api-ms-win-crt-process-l1-1-0.dll", "api-ms-win-crt-runtime-l1-1-0.dll", "api-ms-win-crt-stdio-l1-1-0.dll", "api-ms-win-crt-string-l1-1-0.dll", "api-ms-win-crt-time-l1-1-0.dll", "api-ms-win-crt-utility-l1-1-0.dll", "ucrtbase.dll"], "start": 1648079295.6199462, "end": 1648079311.3544242, "context": null}
[task 2022-03-23T23:48:33.691Z] 23:48:33     INFO -  package> Generating chrome-map for coverage data...
[task 2022-03-23T23:48:33.692Z] 23:48:33     INFO -  package> z:/task_164807469337731/workspace/obj-build/_virtualenvs/build/Scripts/python.exe Z:/task_164807469337731/build/src/mach build-backend -b ChromeMap
[task 2022-03-23T23:48:33.692Z] 23:48:33     INFO -  package> Error running mach:
[task 2022-03-23T23:48:33.692Z] 23:48:33     INFO -  package>
[task 2022-03-23T23:48:33.692Z] 23:48:33     INFO -  package>     ['build-backend', '-b', 'ChromeMap']
[task 2022-03-23T23:48:33.692Z] 23:48:33     INFO -  package>
[task 2022-03-23T23:48:33.693Z] 23:48:33     INFO -  package> The error occurred in code that was called by the mach command. This is either
[task 2022-03-23T23:48:33.693Z] 23:48:33     INFO -  package> a bug in the called code itself or in the way that mach is calling it.
[task 2022-03-23T23:48:33.693Z] 23:48:33     INFO -  package> You can invoke |./mach busted| to check if this issue is already on file. If it
[task 2022-03-23T23:48:33.694Z] 23:48:33     INFO -  package> isn't, please use |./mach busted file build-backend| to report it. If |./mach busted| is
[task 2022-03-23T23:48:33.694Z] 23:48:33     INFO -  package> misbehaving, you can also inspect the dependencies of bug 1543241.
[task 2022-03-23T23:48:33.694Z] 23:48:33     INFO -  package>
[task 2022-03-23T23:48:33.695Z] 23:48:33     INFO -  package> If filing a bug, please include the full output of mach, including this error
[task 2022-03-23T23:48:33.695Z] 23:48:33     INFO -  package> message.
[task 2022-03-23T23:48:33.695Z] 23:48:33     INFO -  package>
[task 2022-03-23T23:48:33.695Z] 23:48:33     INFO -  package> The details of the failure are as follows:
[task 2022-03-23T23:48:33.696Z] 23:48:33     INFO -  package>
[task 2022-03-23T23:48:33.696Z] 23:48:33     INFO -  package> PermissionError: [WinError 5] Access is denied: 'z:/task_164807469337731/workspace/obj-build\\_virtualenvs\\build\\Scripts\\python.exe'
[task 2022-03-23T23:48:33.696Z] 23:48:33     INFO -  package>
[task 2022-03-23T23:48:33.696Z] 23:48:33     INFO -  package>   File "z:\task_164807469337731\build\src\python\mozbuild\mozbuild\base.py", line 863, in activate_virtualenv
[task 2022-03-23T23:48:33.697Z] 23:48:33     INFO -  package>     self.virtualenv_manager.activate()
[task 2022-03-23T23:48:33.697Z] 23:48:33     INFO -  package>   File "Z:\task_164807469337731\build\src\python\mach\mach\site.py", line 597, in activate
[task 2022-03-23T23:48:33.697Z] 23:48:33     INFO -  package>     self.ensure()
[task 2022-03-23T23:48:33.698Z] 23:48:33     INFO -  package>   File "Z:\task_164807469337731\build\src\python\mach\mach\site.py", line 586, in ensure
[task 2022-03-23T23:48:33.698Z] 23:48:33     INFO -  package>     self._metadata,
[task 2022-03-23T23:48:33.698Z] 23:48:33     INFO -  package>   File "Z:\task_164807469337731\build\src\python\mach\mach\site.py", line 1175, in _create_venv_with_pthfile
[task 2022-03-23T23:48:33.698Z] 23:48:33     INFO -  package>     shutil.rmtree(virtualenv_root)
[task 2022-03-23T23:48:33.699Z] 23:48:33     INFO -  package>   File "c:\mozilla-build\python3\lib\shutil.py", line 494, in rmtree
[task 2022-03-23T23:48:33.699Z] 23:48:33     INFO -  package>     return _rmtree_unsafe(path, onerror)
[task 2022-03-23T23:48:33.699Z] 23:48:33     INFO -  package>   File "c:\mozilla-build\python3\lib\shutil.py", line 384, in _rmtree_unsafe
[task 2022-03-23T23:48:33.700Z] 23:48:33     INFO -  package>     _rmtree_unsafe(fullname, onerror)
[task 2022-03-23T23:48:33.700Z] 23:48:33     INFO -  package>   File "c:\mozilla-build\python3\lib\shutil.py", line 389, in _rmtree_unsafe
[task 2022-03-23T23:48:33.700Z] 23:48:33     INFO -  package>     onerror(os.unlink, fullname, sys.exc_info())
[task 2022-03-23T23:48:33.701Z] 23:48:33     INFO -  package>   File "c:\mozilla-build\python3\lib\shutil.py", line 387, in _rmtree_unsafe
[task 2022-03-23T23:48:33.701Z] 23:48:33     INFO -  package>     os.unlink(fullname)
[task 2022-03-23T23:48:33.701Z] 23:48:33    ERROR -  package> mozmake[5]: *** [Z:/task_164807469337731/build/src/toolkit/mozapps/installer/packager.mk:34: stage-package] Error 1
[task 2022-03-23T23:48:33.702Z] 23:48:33     INFO -  package> mozmake[5]: Leaving directory 'z:/task_164807469337731/workspace/obj-build/browser/installer'
[task 2022-03-23T23:48:33.702Z] 23:48:33    ERROR -  package> mozmake[4]: *** [Z:/task_164807469337731/build/src/toolkit/mozapps/installer/packager.mk:111: make-package] Error 2
[task 2022-03-23T23:48:33.702Z] 23:48:33    ERROR -  package> mozmake[3]: *** [Z:/task_164807469337731/build/src/config/rules.mk:352: default] Error 2
[task 2022-03-23T23:48:33.703Z] 23:48:33    ERROR -  package> mozmake[2]: *** [Z:/task_164807469337731/build/src/browser/build.mk:6: package] Error 2
[task 2022-03-23T23:48:33.703Z] 23:48:33    ERROR -  mozmake[1]: *** [Z:/task_164807469337731/build/src/build/moz-automation.mk:110: automation/package] Error 2
[task 2022-03-23T23:48:33.703Z] 23:48:33     INFO -  mozmake[1]: *** Waiting for unfinished jobs....

Comment 1

[Cristian Tuns]

Hello Mitchell, can you please take a look at this? I think this is caused by Bug 1760677. Backfills

Comment 2

[Mitchell Hentges [:mhentges] 🦀]

I bet it was the related patch that landed at the same time.
Digging into this ⛏

Comment 3

[Mitchell Hentges [:mhentges] 🦀]

This is because old versions of Windows Python (pre-3.7.2) are missing this commit, and therefore reference a non-existent $prefix/Scripts/pythonXY.zip.

Comment 4

[Intermittent Failures Robot]

24 failures in 3341 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 24

Platform and build breakdown:

• windows2012-64: 24
  • ccov: 24

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761150&startday=2022-03-21&endday=2022-03-27&tree=all

Comment 5

[Mitchell Hentges [:mhentges] 🦀]

This is because old versions of Windows Python (pre-3.7.2) are missing this commit, and therefore reference a non-existent $prefix/Scripts/pythonXY.zip.

After futzing with this, there's more sys.path-y differences, making that solution insufficient.

Digging more into this, the reason why issues like this keep cropping up is because:

1. When Mach uses the system Python, it inherits its packages
   • Importantly, it doesn't ask the provided Python executable for clean results, it uses what's currently in the sys.path. This was to support the ./mach python --virtualenv psutil ... ./mach build use case
2. When Mach runs subprocesses, some of them may tack on extra sys.path entries
3. To ensure that the command virtualenvs remain consistent, we verify that the existing mach.pth file lines up with what we expect - however, since our only way of calculating a "system-python-using-virtualenv" is to re-derive it from the current sys.path. If we aren't sufficiently clever, then the sys.path additions from point 2 cause the verification to fail.

Fortunately, as of D140257, the ./mach --virtualenv psutil ... ./mach use case no longer exists, so we should be clear to simplify what it means be "extend from the system python", specifically: rather than expanding on the sys.path as-it-is-at-process-time, instead simply build on top of what python3 -c "site.getusersitepackages() + site.getsitepackages()" returns. This is a more objective, less-state-dependent starting point, which means that the "inconsistent <virtualenv> pthfile state" class of errors should be nicely scrubbed from CI.

Comment 6

[Intermittent Failures Robot]

20 failures in 3323 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 20

Platform and build breakdown:

• windows2012-64: 20
  • ccov: 20

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761150&startday=2022-03-28&endday=2022-04-03&tree=all

Comment 7

[Marco Castelluccio [:marco]]

Mitch, any chance we could back-out the original patch? This is causing Windows coverage not to be collected.

Comment 8

[Mitchell Hentges [:mhentges] 🦀]

I'll do you one better: I think my local patch to fix this problem is in a state where it can be reviewed and soon landed. Let's push that direction first, if possible.

I'll have it up shortly later today.

Comment 9

[Mitchell Hentges [:mhentges] 🦀]

Attachment: Bug 1761150: Mach should use fresh system python, don't inherit sys.path

Previously, when using the system Python packages, Mach would reuse the
values already existing in the sys.path. This had two benefits:

1. We didn't have to do work to calculate which paths the "system
   Python" specifically referred to.
2. This allowed us to support nested Mach calls
   (such as ./mach --virtualenv psutil ./mach build).

However, it came with its own headaches, specifically around "consistent
imports" and Python subprocesses, such as in the following example

1. Mach runs "using system Python"
2. The "build" site (for example) would be activated. The current
   sys.path is included in the virtualenv's mach.pth file so that
   subprocesses will have access to the same packages as the primary
   Mach process
3. //Something// adds something to the sys.path
4. The build virtualenv is redundantly re-activated (such as due to
   generic setup code for some module). Though we don't physically
   re-activate the virtualenv, we //do// check that it's up-to-date to
   validate assumptions - and it's not! It's missing the
   //something// that was added to the sys.path.
5. We can't re-create the build virtualenv because it's already active,
   so:
6. An error is raised so that unexpected out-of-date-ness doesn't fly
   under the radar.

---

This patch solves this by calculating the "system Python" paths in a
deterministic way. Then, even when using the system Python, the Mach and
command sites use define themselves in a consistent way.

This means that we can't do ./mach --virtualenv <venv> ./mach ... to
shares venv's packages with the whole new Mach process. Fortunately,
this has been replaced with moving such packages into the nested Mach
command's requirements definition instead.

TL;DR: more consistent, less failures. 👍

Comment 10

[Intermittent Failures Robot]

23 failures in 2922 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

This is the #49 most frequent failure this week.

Repository breakdown:

• mozilla-central: 22
• autoland: 1

Platform and build breakdown:

• windows2012-64: 23
  • ccov: 23

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761150&startday=2022-04-04&endday=2022-04-10&tree=all

Comment 11

[Marco Castelluccio [:marco]]

Mitch, what's the status of this? Do you think it can be landed soon? We are getting a few complaints about code coverage missing for Windows.

Comment 12

[Mitchell Hentges [:mhentges] 🦀]

Hey Marco, :ahal should be able to review this this afternoon.
If he's not able to, or if nontrivial changes are requested, I'll do a backout instead. Sorry for the downtime here :)

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/76ca62e02f73
Mach should use fresh system python, don't inherit sys.path r=ahal

Comment 14

[Cristina Cozmuta (:CrissCozmuta)]

https://hg.mozilla.org/mozilla-central/rev/76ca62e02f73

Comment 15

[Intermittent Failures Robot]

5 failures in 2948 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 5

Platform and build breakdown:

• windows2012-64: 5
  • ccov: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761150&startday=2022-04-11&endday=2022-04-17&tree=all