Bug 1385459

User-Agent:       Mozilla/5.0 (Windows NT 6.1; WOW64; rv:44.0) Gecko/20100101 Firefox/44.0
Build Identifier: 

When 'rhcert-backend run --test=openstack_verify', there's no output during tempest runs, nor after tempest completes.



Reproducible: Always

Steps to Reproduce:
1.install redhat openstack platform
2.install redhat certification program 
  yum install redhat-certification redhat-certification-openstack
3.run cert program
  rhcert-backend run --test=openstack_verify
Actual Results:  
...
Subtest: Tempest - Run Tempest
Running tempest
/tmp/tmpEZqLHK_tempest/tempest/run_tempest.sh -N -C /tmp/tmpEZqLHK_tempest/tempest/tempest.conf --serial tempest.api.volume tempest.scenario.test_encrypted_cinder_volumes  tempest.scenario.test_minimum_basic  tempest.scenario.test_snapshot_pattern  tempest.scenario.test_stamp_pattern  tempest.scenario.test_volume_boot_pattern
cd
Error: tempest run failed
"/tmp/tmpEZqLHK_tempest/tempest/run_tempest.sh -N -C /tmp/tmpEZqLHK_tempest/tempest/tempest.conf --serial tempest.api.volume tempest.scenario.test_encrypted_cinder_volumes  tempest.scenario.test_minimum_basic  tempest.scenario.test_snapshot_pattern  tempest.scenario.test_stamp_pattern  tempest.scenario.test_volume_boot_pattern " has output on stderr
FAIL

Subtest: OS report - Gather system information
...


Expected Results:  
There should be output during tempest run.
======
...
Subtest: Tempest - Run Tempest
Running tempest
/tmp/tmpczblyL_tempest/tempest/run_tempest.sh -N -C /tmp/tmpczblyL_tempest/tempest/tempest.conf --serial tempest.api.volume tempest.scenario.test_encrypted_cinder_volumes  tempest.scenario.test_minimum_basic  tempest.scenario.test_snapshot_pattern  tempest.scenario.test_stamp_pattern  tempest.scenario.test_volume_boot_pattern
running=OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
OS_TEST_TIMEOUT=${OS_TEST_TIMEOUT:-500} \
OS_TEST_LOCK_PATH=${OS_TEST_LOCK_PATH:-${TMPDIR:-'/tmp'}} \
${PYTHON:-python} -m subunit.run discover -t ${OS_TOP_LEVEL:-./} ${OS_TEST_PATH:-./tempest/test_discover} --list
running=OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
OS_TEST_TIMEOUT=${OS_TEST_TIMEOUT:-500} \
OS_TEST_LOCK_PATH=${OS_TEST_LOCK_PATH:-${TMPDIR:-'/tmp'}} \
${PYTHON:-python} -m subunit.run discover -t ${OS_TOP_LEVEL:-./} ${OS_TEST_PATH:-./tempest/test_discover}  --load-list /tmp/tmp0FwwQO
{0} tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendV1Test.test_backend_name_distinction [0.433791s] ... ok
{0} tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendV1Test.test_backend_name_distinction_with_prefix [0.437616s] ... ok
{0} tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendV1Test.test_backend_name_reporting [0.443775s] ... ok
{0} tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendV1Test.test_backend_name_reporting_with_prefix [0.473120s] ... ok
{0} tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendV2Test.test_backend_name_distinction [0.432178s] ... ok
{0} tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendV2Test.test_backend_name_distinction_with_prefix [0.429922s] ... ok
{0} tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendV2Test.test_backend_name_reporting [0.414504s] ... ok
{0} tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendV2Test.test_backend_name_reporting_with_prefix [0.414306s] ... ok
{0} tempest.api.volume.admin.test_snapshots_actions.SnapshotsActionsV1Test.test_reset_snapshot_status [0.570296s] ... ok
...
======

There's a mistake in sequence of method calls in 'echo' of /usr/lib/python2.7/site-packages/rhcert/command.py
======
    def echo(self, ignoreErrors=False):
        """ output is equivalent to run, except that the commands' output
            is echo'd on stdout. """
        self._run()
        if not ignoreErrors:
            self._checkErrors()
        self.printOutput()
        return 0

======

self._checkErrors() should be moved after self.printOutput(), like below 
======
    def echo(self, ignoreErrors=False):
        """ output is equivalent to run, except that the commands' output
            is echo'd on stdout. """
        self._run()
        self.printOutput()  #output before _checkErrors
        if not ignoreErrors:
            self._checkErrors()
        return 0
======

Otherwise if there's any error output(even warning messages) during tempest run, it will raise exception which would cause premature termination of the program and self.printOutput() will get on chance to run.
======
def _checkErrors(self):

    if self.errors and len(self.errors) > 0:
        raise HwCertCommandErrorOutput(self) # <<== raise exception if there's any error message.
    self._checkReturnValue()
...

#/usr/lib/python2.7/site-packages/rhcert/suites/openstack/verify.py
def core(self):
    if not self.exit:
        return self.exit

    returnValue = True
    print("Running tempest")
    tempest = Command('%s -N -C %s --serial %s' % (os.path.join(self.temp_dir,
                                       'tempest', 'run_tempest.sh'),
                                       self.tempest_conf,
                                       self.test_regex))
    print(tempest.command)
    try:
        tempest.echo()  #<<== raise exception
    except HwCertCommandException as error:
        print "Error: tempest run failed"  
        print error
        returnValue = False
======

But there's another issue, even by moving self.printOutput() before self._checkErrors. There's no output during tempest runs, the output will only be available after tempest completes.

This is because we wait until tempest completes in our code
======
#/usr/lib/python2.7/site-packages/rhcert/command.py
def _run(self):
    # commandPipe = popen2.Popen3(self.command, capturestderr=True)
    self.pipe = subprocess.Popen(self.command, shell=True,
                    stdin=subprocess.PIPE,
                    stdout=subprocess.PIPE,
                    stderr=subprocess.PIPE,)
    (output, errors) = self.pipe.communicate() #<<==Wait for process to terminate
    if output:
        self.output = output.splitlines()
    if errors:
        self.errors = errors.splitlines()
    self.signal = 0
    self.returnValue = 0
    if self.pipe.returncode < 0:
        self.signal = self.pipe.returncode
    else:
        self.returnValue = self.pipe.returncode
======

We should change this to show output during command runs so that users know what's going on instead of just wait for command to complete to output everything.

eg: something like this.
======
            while True:
                line = self.pipe.stdout.readline()
                if line:
                    sys.stdout.write(line)
                else:
                    break
======

or use 'check_output' like redhat-certification-backend-2.8-20160819 does.