Cleanup Zuul's stdout/stderr output

This is primarily an issue in the unittests, but we also cleanup a
problem with output in ansible package installation verification.

There are two types of issue we address here. The first is unittests
calling print(). We replace those with log.info() calls to keep this
information from adding noise to the stestr output. The second is
subprocess.run() not capturing output so it ends up on stdout/stderr. In
this case we update use of subprocess.run() to capture the output, then
log/error appropriately if the return code is not 0.

Change-Id: I22650bf9495d3fe71bdf4a2dec5d9b3f30116188

tests/unit/test_executor.py

@@ -940,7 +940,14 @@ class TestExecutorExtraPackages(AnsibleZuulTestCase):
         for version in ansible_manager._supported_versions:
             command = [ansible_manager.getAnsibleCommand(version, 'pip'),
                        'uninstall', '-y', self.test_package]
-            subprocess.run(command)
+            # We want to error if the uninstall fails as the test below
+            # relies on the package not being installed to be properly
+            # exercised.
+            s = subprocess.run(command,
+                               stdout=subprocess.PIPE,
+                               stderr=subprocess.STDOUT)
+            self.log.info(s.stdout)
+            self.assertEqual(s.returncode, 0)
 
     @mock.patch('zuul.lib.ansible.ManagedAnsible.extra_packages',
                 new_callable=mock.PropertyMock)

tests/unit/test_gerrit.py

@@ -544,7 +544,7 @@ class TestChecksApi(ZuulTestCase):
         self.executor_server.hold_jobs_in_build = False
         self.executor_server.release()
         self.waitUntilSettled()
-        print(A.checks_history)
+        self.log.info(A.checks_history)
         self.assertEqual(A.checks_history[3]['zuul:check']['state'],
                          'NOT_STARTED')
         self.assertEqual(A.checks_history[4]['zuul:check']['state'],

tests/unit/test_scheduler.py

@@ -6966,7 +6966,7 @@ class TestDependencyGraph(ZuulTestCase):
         self.assertHistory([])
         self.assertEqual(len(A.messages), 1)
         self.assertTrue('Job project-merge not defined' in A.messages[0])
-        print(A.messages)
+        self.log.info(A.messages)
 
     @simple_layout('layouts/soft-dependencies.yaml')
     def test_soft_dependencies(self):

zuul/lib/ansible.py

@@ -231,7 +231,7 @@ class AnsibleManager:
         return result
 
     def _validate_packages(self, version):
-        result = True
+        result = False
         try:
             extra_packages = self._getAnsible(version).extra_packages
             python_package_check = \
@@ -240,11 +240,22 @@ class AnsibleManager:
 
             command = [self.getAnsibleCommand(version, 'python'),
                        '-c', python_package_check]
-            subprocess.run(command, check=True)
+            ret = subprocess.run(command,
+                                 stdout=subprocess.PIPE,
+                                 stderr=subprocess.STDOUT)
+            # We check manually so that we can log the stdout and stderr
+            # properly which aren't going to be available if we have
+            # subprocess.run() check and raise.
+            if ret.returncode != 0:
+                self.log.error(
+                    'Ansible version %s installation is missing packages' %
+                    version)
+                self.log.debug("Ansible package check output: %s", ret.stdout)
+            else:
+                result = True
         except Exception:
-            result = False
             self.log.exception(
-                'Ansible version %s installation is missing packages' %
+                'Exception checking Ansible version %s packages' %
                 version)
         return result