1053197 - Failures during install_module() are shown as ERRORs in the log even though the run succeeded

Status: RESOLVED FIXED

(Release Engineering :: Applications: MozharnessCore, defect)

Description

[Ed Morley [:emorley]]

This run passed, however the log shows:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45831722&tree=Mozilla-Inbound

{
03:30:50     INFO -  Installing collected packages: psutil
03:30:50     INFO -    Running setup.py install for psutil
03:30:50     INFO -      building '_psutil_mswindows' extension
03:30:50     INFO -      error: Unable to find vcvarsall.bat
03:30:50     INFO -      Complete output from command C:\slave\test\build\venv\Scripts\python.exe -c "import setuptools;__file__='C:\\slave\\test\\build\\venv\\build\\psutil\\setup.py';execfile(__file__)" install --single-version-externally-managed --record c:\docume~1\cltbld~1.t-x\locals~1\temp\pip-o1qsah-record\install-record.txt --install-headers C:\slave\test\build\venv\include\site\python2.7:
03:30:50     INFO -      running install
03:30:50     INFO -  running build
03:30:50     INFO -  running build_py
03:30:50     INFO -  creating build
03:30:50     INFO -  creating build\lib.win32-2.7
03:30:50     INFO -  creating build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\error.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\_common.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\_compat.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\_error.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\_psbsd.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\_pslinux.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\_psmswindows.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\_psosx.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\_psposix.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  copying psutil\__init__.py -> build\lib.win32-2.7\psutil
03:30:50     INFO -  running build_ext
03:30:50     INFO -  building '_psutil_mswindows' extension
03:30:50     INFO -  error: Unable to find vcvarsall.bat
03:30:50     INFO -  ----------------------------------------
03:30:50     INFO -  Command C:\slave\test\build\venv\Scripts\python.exe -c "import setuptools;__file__='C:\\slave\\test\\build\\venv\\build\\psutil\\setup.py';execfile(__file__)" install --single-version-externally-managed --record c:\docume~1\cltbld~1.t-x\locals~1\temp\pip-o1qsah-record\install-record.txt --install-headers C:\slave\test\build\venv\include\site\python2.7 failed with error code 1
03:30:50     INFO -  Storing complete log in C:\Documents and Settings\cltbld.T-XP32-IX-060\Application Data\pip\pip.log
03:30:50     INFO - Return code: 1
03:30:50    ERROR - <bound method DesktopUnittest.run_command of <__main__.DesktopUnittest object at 0x00EA1F10>> failed after 1 tries!
03:30:50  WARNING - Error running install of optional package, C:\slave\test\build\venv\Scripts\pip install --download-cache C:\slave\test\build\venv\cache --timeout 120 --no-index --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub psutil==0.7.1.
03:30:50     INFO - Installing mozsystemmonitor==0.0.0 into virtualenv C:\slave\test\build\venv
03:30:50     INFO - retry: Calling <bound method DesktopUnittest.run_command of <__main__.DesktopUnittest object at 0x00EA1F10>> with args: [['C:\\slave\\test\\build\\venv\\Scripts\\pip', 'install', '--download-cache', 'C:\\slave\\test\\build\\venv\\cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'mozsystemmonitor==0.0.0']], kwargs: {'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x00B7C3A0>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x00ADED40>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x00B2E6D8>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x00BF2368>, 'level': 'warning'}, {'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': <_sre.SRE_Pattern object at 0x00A7ABD0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x00BDA700>, 'level': 'critical'}], 'cwd': 'C:\\slave\\test\\build', 'success_codes': [0, 1]}, attempt #1
03:30:50     INFO - Running command: ['C:\\slave\\test\\build\\venv\\Scripts\\pip', 'install', '--download-cache', 'C:\\slave\\test\\build\\venv\\cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'mozsystemmonitor==0.0.0'] in C:\slave\test\build
03:30:50     INFO - Copy/paste: C:\slave\test\build\venv\Scripts\pip install --download-cache C:\slave\test\build\venv\cache --timeout 120 --no-index --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub mozsystemmonitor==0.0.0
03:30:51     INFO -  Ignoring indexes: http://pypi.python.org/simple/
03:30:51     INFO -  Downloading/unpacking mozsystemmonitor==0.0.0
03:30:51     INFO -    Downloading mozsystemmonitor-0.0.tar.gz
03:30:51     INFO -    Storing download in cache at c:\slave\test\build\venv\cache\http%3a%2f%2fpypi.pvt.build.mozilla.org%2fpub%2fmozsystemmonitor-0.0.tar.gz
03:30:51     INFO -    Running setup.py egg_info for package mozsystemmonitor
03:30:51     INFO -  Downloading/unpacking psutil>=0.7.1 (from mozsystemmonitor==0.0.0)
03:30:51     INFO -    Running setup.py egg_info for package psutil
03:30:51     INFO -  Installing collected packages: mozsystemmonitor, psutil
03:30:51     INFO -    Running setup.py install for mozsystemmonitor
03:30:51     INFO -    Running setup.py install for psutil
03:30:51     INFO -      building '_psutil_mswindows' extension
03:30:51     INFO -      error: Unable to find vcvarsall.bat
03:30:51     INFO -      Complete output from command C:\slave\test\build\venv\Scripts\python.exe -c "import setuptools;__file__='C:\\slave\\test\\build\\venv\\build\\psutil\\setup.py';execfile(__file__)" install --single-version-externally-managed --record c:\docume~1\cltbld~1.t-x\locals~1\temp\pip-i7zcw1-record\install-record.txt --install-headers C:\slave\test\build\venv\include\site\python2.7:
03:30:51     INFO -      running install
03:30:51     INFO -  running build
03:30:51     INFO -  running build_py
03:30:51     INFO -  running build_ext
03:30:51     INFO -  building '_psutil_mswindows' extension
03:30:51     INFO -  error: Unable to find vcvarsall.bat
03:30:51     INFO -  ----------------------------------------
03:30:51     INFO -  Command C:\slave\test\build\venv\Scripts\python.exe -c "import setuptools;__file__='C:\\slave\\test\\build\\venv\\build\\psutil\\setup.py';execfile(__file__)" install --single-version-externally-managed --record c:\docume~1\cltbld~1.t-x\locals~1\temp\pip-i7zcw1-record\install-record.txt --install-headers C:\slave\test\build\venv\include\site\python2.7 failed with error code 1
03:30:51     INFO -  Storing complete log in C:\Documents and Settings\cltbld.T-XP32-IX-060\Application Data\pip\pip.log
03:30:51     INFO - Return code: 1
03:30:51    ERROR - <bound method DesktopUnittest.run_command of <__main__.DesktopUnittest object at 0x00EA1F10>> failed after 1 tries!
}

The mozharness ERROR log level causes the log line to be highlighted in TBPL and thus cause confusion when viewing the error summary of jobs that have failed, since it's not apparent that the log lines above were not the root cause of the actual failure.

Pete, is this fallout from bug 1007230?

Comment 1

[Ed Morley [:emorley]]

The examples in comment 0 were windows, these are OS X:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45826131&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=45826010&tree=Mozilla-Inbound

Tweaking summary since they are not retries - just presumably errors that were previously being ignored - ie: search for "unable to execute gcc: No such file or directory" in a log from before bug 1007230:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45605318&full=1&branch=mozilla-inbound

My thoughts:
1) If these failures are bad, then they should continue to be labelled with log level ERROR, but should also abort the run.
2) If we aren't going to abort the run, then the log level should be WARNING or INFO.

Comment 2

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

(In reply to Ed Morley [:edmorley] from comment #0)

> Pete, is this fallout from bug 1007230?

Indeed! I'll attach two patches - the first a "minimum" to fix the issue, and a second to clean up the mozharness code a little. The second is a "nice to have" only.

Comment 3

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Attachment: bug1053197_mozharness_minimum_v1.patch

This should fix the immediate issue.

Comment 4

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Attachment: bug1053197_mozharness_cleanup_v1.patch

This is a bit of a clean up, including implementing the outstanding "TODO" for error_level override that was mentioned in the comments for run_command method.

Previously, success codes was listed as 0 or 1 for the pip install for optional packages, which I thought was a bit of a hack (since any error should only be displayed as a warning, and to say 1 is a success code would means the install was successful if we get a return code of 1, which is not true) so I switched this to use the newly implementing adjusted logging level, by logging errors at WARNING for optional package installations.

Comment 5

[Ed Morley [:emorley]]

That's great - thank you :-)

Comment 6

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

I have a win xp test pending (same job as in comment 0):

https://tbpl.mozilla.org/?tree=Ash&rev=e93c20d7930b&jobname=Windows%20XP%2032-bit%20ash%20debug%20test%20reftest

I'm guessing since it is win xp, there might be quite a wait time, so I'll leave this now and come back to it later.

This is testing the "mimimum" patch (https://bugzilla.mozilla.org/attachment.cgi?id=8472886) and not the cleanup.

Comment 7

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Yaaay. Success on ash:

04:30:30     INFO -  Installing collected packages: psutil
04:30:30     INFO -    Running setup.py install for psutil
04:30:30     INFO -      building '_psutil_mswindows' extension
04:30:30     INFO -      error: Unable to find vcvarsall.bat
04:30:30     INFO -      Complete output from command C:\slave\test\build\venv\Scripts\python.exe -c "import setuptools;__file__='C:\\slave\\test\\build\\venv\\build\\psutil\\setup.py';execfile(__file__)" install --single-version-externally-managed --record c:\docume~1\cltbld~1.t-x\locals~1\temp\pip-l712y7-record\install-record.txt --install-headers C:\slave\test\build\venv\include\site\python2.7:
04:30:30     INFO -      running install
04:30:30     INFO -  running build
04:30:30     INFO -  running build_py
04:30:30     INFO -  creating build
04:30:30     INFO -  creating build\lib.win32-2.7
04:30:30     INFO -  creating build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\error.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\_common.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\_compat.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\_error.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\_psbsd.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\_pslinux.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\_psmswindows.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\_psosx.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\_psposix.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  copying psutil\__init__.py -> build\lib.win32-2.7\psutil
04:30:30     INFO -  running build_ext
04:30:30     INFO -  building '_psutil_mswindows' extension
04:30:30     INFO -  error: Unable to find vcvarsall.bat
04:30:30     INFO -  ----------------------------------------
04:30:30     INFO -  Command C:\slave\test\build\venv\Scripts\python.exe -c "import setuptools;__file__='C:\\slave\\test\\build\\venv\\build\\psutil\\setup.py';execfile(__file__)" install --single-version-externally-managed --record c:\docume~1\cltbld~1.t-x\locals~1\temp\pip-l712y7-record\install-record.txt --install-headers C:\slave\test\build\venv\include\site\python2.7 failed with error code 1
04:30:30     INFO -  Storing complete log in C:\Documents and Settings\cltbld.T-XP32-IX-003\Application Data\pip\pip.log
04:30:30     INFO - Return code: 1
04:30:30  WARNING - <bound method DesktopUnittest.run_command of <__main__.DesktopUnittest object at 0x00F463D0>> failed after 1 tries!
04:30:30  WARNING - Error running install of optional package, C:\slave\test\build\venv\Scripts\pip install --download-cache C:\slave\test\build\venv\cache --timeout 120 --no-index --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub psutil==0.7.1.
04:30:30     INFO - Installing mozsystemmonitor==0.0.0 into virtualenv C:\slave\test\build\venv
04:30:30     INFO - retry: Calling <bound method DesktopUnittest.run_command of <__main__.DesktopUnittest object at 0x00F463D0>> with args: [['C:\\slave\\test\\build\\venv\\Scripts\\pip', 'install', '--download-cache', 'C:\\slave\\test\\build\\venv\\cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'mozsystemmonitor==0.0.0']], kwargs: {'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x00BDE3A0>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x00ADED40>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x00B3FD80>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x00BEC368>, 'level': 'warning'}, {'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': <_sre.SRE_Pattern object at 0x00A7ABD0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x00BDF700>, 'level': 'critical'}], 'cwd': 'C:\\slave\\test\\build', 'success_codes': [0, 1]}, attempt #1

Comment 8

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Now I'll add the second patch, and test that on ash too (the "cleanup" patch)...

Comment 9

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Also testing on OS X, as there is a long wait time for xp machines...

Patched mochitest-2 on OS X 10.6 debug:
https://tbpl.mozilla.org/?tree=Ash&rev=e93c20d7930b&jobname=Rev4%20MacOSX%20Snow%20Leopard%2010.6%20ash%20debug%20test%20mochitest-2

vs.

Unpatched mochitest-2 on OS X 10.6 debug (first link from Ed in comment 1):
https://tbpl.mozilla.org/php/getParsedLog.php?id=45826131&tree=Mozilla-Inbound

Comment 10

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Oh dear, patch ("cleanup") failed - and now I need to pop out - I'll be back a bit later to fix this.

Please note, patch 1 (the "minimum" patch) is tested and working. :)

Pete

Comment 11

[Jordan Lund (:jlund)]

Comment on attachment 8472886 [details] [diff] [review]
bug1053197_mozharness_minimum_v1.patch

Review of attachment 8472886 [details] [diff] [review]:
-----------------------------------------------------------------

lgtm pete!

just thinking here, if we just used error_level and error_message from retry method signature, could we not just do something like:

# retry args
attempts = 1 if optional else None
error_level = WARNING if optional else FATAL
error_message = "Error running install of package, %s!" % ' '.join(command) # regardless of optional
good_statuses = (0,) # regardless of optional


# run_command args
success_codes = [0] # regardless of optional. note this is the default in run_command so we don't even need it

that way 1) only attempts and error_level care about optional 2) we don't have to check for `if retry() != 0` 3) we don't need to write self.warning or self.fatal with the same message depending on optional at the end

am I missing something or is that much simplier and fixes all our issues here. Won't look at the 'nice to have' patch that recently failed till you get back.

Thanks for testing on ash! :)

Comment 13

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Landed part 1: https://bugzilla.mozilla.org/attachment.cgi?id=8472886

default:     https://hg.mozilla.org/build/mozharness/rev/a82549185231
production:  https://hg.mozilla.org/build/mozharness/rev/0dcd4dc00267

Comment 14

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

d'oh!

-            error_message='Command: %s failed after %(attempts)d tries!' % quoted_command,
+            error_message='Command: ' + quoted_command + ' failed after %(attempts)d tries!',

Now testing again on ash...

Comment 15

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

(In reply to Jordan Lund (:jlund) from comment #11)
> Comment on attachment 8472886 [details] [diff] [review]
> bug1053197_mozharness_minimum_v1.patch
> 
> Review of attachment 8472886 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> lgtm pete!
> 
> just thinking here, if we just used error_level and error_message from retry
> method signature, could we not just do something like:
> 
> # retry args
> attempts = 1 if optional else None
> error_level = WARNING if optional else FATAL
> error_message = "Error running install of package, %s!" % ' '.join(command)
> # regardless of optional
> good_statuses = (0,) # regardless of optional
> 
> 
> # run_command args
> success_codes = [0] # regardless of optional. note this is the default in
> run_command so we don't even need it
> 
> that way 1) only attempts and error_level care about optional 2) we don't
> have to check for `if retry() != 0` 3) we don't need to write self.warning
> or self.fatal with the same message depending on optional at the end
> 
> am I missing something or is that much simplier and fixes all our issues
> here. Won't look at the 'nice to have' patch that recently failed till you
> get back.
> 
> Thanks for testing on ash! :)

I think this is pretty much what I put in my second patch! :D
I guess we reached the same conclusions. :)

Comment 16

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Second patch looks ok now with the fix from comment 14:

https://tbpl.mozilla.org/php/getParsedLog.php?id=45978957&tree=Ash&full=1

Failure further down was unrelated.

Comment 17

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Attachment: bug1053197_mozharness_cleanup_v2.patch

Same as before, now with fix from comment 14.

Comment 18

[Jordan Lund (:jlund)]

Comment on attachment 8473379 [details] [diff] [review]
bug1053197_mozharness_cleanup_v2.patch

Review of attachment 8473379 [details] [diff] [review]:
-----------------------------------------------------------------

I'll be taking a look at this tomorrow. Sorry for the inconvenience.

Comment 19

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Attachment: bug1053197_mozharness_cleanup_v3.patch

Good that you waited ;)

Tweaked a little more. And tested numerous times on Ash with various scenarios.

Thanks Jordan!
Pete

Comment 20

[Jordan Lund (:jlund)]

Comment on attachment 8473578 [details] [diff] [review]
bug1053197_mozharness_cleanup_v3.patch

Review of attachment 8473578 [details] [diff] [review]:
-----------------------------------------------------------------

lgtm pete :)

Comment 21

[Pete Moore [:pmoore][:pete] [PTO until 13 April 2026]]

Comment on attachment 8473578 [details] [diff] [review]
bug1053197_mozharness_cleanup_v3.patch

Landed.

default:     https://hg.mozilla.org/build/mozharness/rev/48cd98ca43b1
production:  https://hg.mozilla.org/build/mozharness/rev/7771c9623c92