This module should not write directly to stdout/stderr. Instead, it
should either raise exceptions or just log the messages and let the
callers handle them and decide what to do. For example, scripts could
choose to send the log messages stderr or/and write them to a file if
verbose or debugging mode is enabled.

This patch replaces the writes to stderr by an exception in the
send_fd_scm() when _socket_scm_helper is not set or not present. In the
same method, the subprocess Popen will now redirect the stdout/stderr to
logging.debug instead of writing to system stderr. As consequence, since
the Popen.communicate() is now used (in order to get the stdout), the
further call to wait() became redundant and was replaced by
Popen.returncode.

The shutdown() message on negative exit code will now be logged
to logging.warn instead of written to system stderr.

Signed-off-by: Amador Pahim <apahim@redhat.com>
---
 scripts/qemu.py | 30 ++++++++++++++++++++++--------
 1 file changed, 22 insertions(+), 8 deletions(-)

diff --git a/scripts/qemu.py b/scripts/qemu.py
index 0ae5d39414..aca6fa4d82 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -13,6 +13,7 @@
 #
 
 import errno
+import logging
 import string
 import os
 import sys
@@ -20,6 +21,15 @@ import subprocess
 import qmp.qmp
 
 
+LOG = logging.getLogger(__name__)
+
+
+class QEMUMachineError(Exception):
+    """
+    Exception called when an error in QEMUMachine happens.
+    """
+
+
 class QEMUMachine(object):
     '''A QEMU VM'''
 
@@ -62,18 +72,21 @@ class QEMUMachine(object):
         # In iotest.py, the qmp should always use unix socket.
         assert self._qmp.is_scm_available()
         if self._socket_scm_helper is None:
-            print >>sys.stderr, "No path to socket_scm_helper set"
-            return -1
+            raise QEMUMachineError("No path to socket_scm_helper set")
         if os.path.exists(self._socket_scm_helper) == False:
-            print >>sys.stderr, "%s does not exist" % self._socket_scm_helper
-            return -1
+            raise QEMUMachineError("%s does not exist" %
+                                   self._socket_scm_helper)
         fd_param = ["%s" % self._socket_scm_helper,
                     "%d" % self._qmp.get_sock_fd(),
                     "%s" % fd_file_path]
         devnull = open('/dev/null', 'rb')
-        p = subprocess.Popen(fd_param, stdin=devnull, stdout=sys.stdout,
-                             stderr=sys.stderr)
-        return p.wait()
+        p = subprocess.Popen(fd_param, stdin=devnull, stdout=subprocess.PIPE,
+                             stderr=subprocess.STDOUT)
+        output = p.communicate()[0]
+        if output:
+            LOG.debug(output)
+
+        return p.returncode
 
     @staticmethod
     def _remove_if_exists(path):
@@ -154,7 +167,8 @@ class QEMUMachine(object):
 
             exitcode = self._popen.wait()
             if exitcode < 0:
-                sys.stderr.write('qemu received signal %i: %s\n' % (-exitcode, ' '.join(self._args)))
+                LOG.warn('qemu received signal %i: %s', -exitcode,
+                          ' '.join(self._args))
             self._load_io_log()
             self._post_shutdown()
 
-- 
2.13.5

On Fri, 09/01 13:28, Amador Pahim wrote:
> This module should not write directly to stdout/stderr. Instead, it
> should either raise exceptions or just log the messages and let the
> callers handle them and decide what to do. For example, scripts could
> choose to send the log messages stderr or/and write them to a file if
> verbose or debugging mode is enabled.
> 
> This patch replaces the writes to stderr by an exception in the
> send_fd_scm() when _socket_scm_helper is not set or not present. In the
> same method, the subprocess Popen will now redirect the stdout/stderr to
> logging.debug instead of writing to system stderr. As consequence, since
> the Popen.communicate() is now used (in order to get the stdout), the
> further call to wait() became redundant and was replaced by
> Popen.returncode.
> 
> The shutdown() message on negative exit code will now be logged
> to logging.warn instead of written to system stderr.
> 
> Signed-off-by: Amador Pahim <apahim@redhat.com>

Reviewed-by: Fam Zheng <famz@redhat.com>

Am 01.09.2017 um 13:28 hat Amador Pahim geschrieben:
> This module should not write directly to stdout/stderr. Instead, it
> should either raise exceptions or just log the messages and let the
> callers handle them and decide what to do. For example, scripts could
> choose to send the log messages stderr or/and write them to a file if
> verbose or debugging mode is enabled.
> 
> This patch replaces the writes to stderr by an exception in the
> send_fd_scm() when _socket_scm_helper is not set or not present. In the
> same method, the subprocess Popen will now redirect the stdout/stderr to
> logging.debug instead of writing to system stderr. As consequence, since
> the Popen.communicate() is now used (in order to get the stdout), the
> further call to wait() became redundant and was replaced by
> Popen.returncode.
> 
> The shutdown() message on negative exit code will now be logged
> to logging.warn instead of written to system stderr.
> 
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> ---
>  scripts/qemu.py | 30 ++++++++++++++++++++++--------
>  1 file changed, 22 insertions(+), 8 deletions(-)
> 
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index 0ae5d39414..aca6fa4d82 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -13,6 +13,7 @@
>  #
>  
>  import errno
> +import logging
>  import string
>  import os
>  import sys
> @@ -20,6 +21,15 @@ import subprocess
>  import qmp.qmp
>  
>  
> +LOG = logging.getLogger(__name__)

This logger isn't properly initialised, so whenever it would actually be
used, the only thing that ends up in the qemu-iotests output is:

+No handlers could be found for logger "qemu"

The actual error message (that was previously logged to stderr) doesn't
make it to the output any more.

I find it sad how the recent test infrastructure "improvements" tend to
break the tests instead of making them easier to work with. Please be a
bit more careful when touching this code, and *test* your code before
you submit it. I expect from anyone that they test their code, but if we
don't even manage to do that for the tests themselves, I'm losing hope.

Kevin

On Thu, Sep 21, 2017 at 12:35:08PM +0200, Kevin Wolf wrote:
> Am 01.09.2017 um 13:28 hat Amador Pahim geschrieben:
> > This module should not write directly to stdout/stderr. Instead, it
> > should either raise exceptions or just log the messages and let the
> > callers handle them and decide what to do. For example, scripts could
> > choose to send the log messages stderr or/and write them to a file if
> > verbose or debugging mode is enabled.
> > 
> > This patch replaces the writes to stderr by an exception in the
> > send_fd_scm() when _socket_scm_helper is not set or not present. In the
> > same method, the subprocess Popen will now redirect the stdout/stderr to
> > logging.debug instead of writing to system stderr. As consequence, since
> > the Popen.communicate() is now used (in order to get the stdout), the
> > further call to wait() became redundant and was replaced by
> > Popen.returncode.
> > 
> > The shutdown() message on negative exit code will now be logged
> > to logging.warn instead of written to system stderr.
> > 
> > Signed-off-by: Amador Pahim <apahim@redhat.com>
> > ---
> >  scripts/qemu.py | 30 ++++++++++++++++++++++--------
> >  1 file changed, 22 insertions(+), 8 deletions(-)
> > 
> > diff --git a/scripts/qemu.py b/scripts/qemu.py
> > index 0ae5d39414..aca6fa4d82 100644
> > --- a/scripts/qemu.py
> > +++ b/scripts/qemu.py
> > @@ -13,6 +13,7 @@
> >  #
> >  
> >  import errno
> > +import logging
> >  import string
> >  import os
> >  import sys
> > @@ -20,6 +21,15 @@ import subprocess
> >  import qmp.qmp
> >  
> >  
> > +LOG = logging.getLogger(__name__)
> 
> This logger isn't properly initialised, so whenever it would actually be
> used, the only thing that ends up in the qemu-iotests output is:
> 
> +No handlers could be found for logger "qemu"
> 
> The actual error message (that was previously logged to stderr) doesn't
> make it to the output any more.
> 
> I find it sad how the recent test infrastructure "improvements" tend to
> break the tests instead of making them easier to work with. Please be a
> bit more careful when touching this code, and *test* your code before
> you submit it. I expect from anyone that they test their code, but if we
> don't even manage to do that for the tests themselves, I'm losing hope.

Is the test that was broken triggered as part of "make check"?
What can we do to ensure it is?

-- 
Eduardo