[Qemu-devel] [PATCH v6 0/7] scripts/qemu.py fixes and cleanups

[Qemu-devel] [PATCH v6 0/7] scripts/qemu.py fixes and cleanups

[Amador Pahim]

Changes v1->v2:
 - Style fixes to make checkpatch.pl happy.
 - Rebased.
Changes v2->v3:
 - Fix typo in patch 3 ("qemu.py: make 'args' public") commit message.
Changes v3->v4:
 - Squash the 2 first commits since they are co-dependant.
 - Cleanup launch() and shutdown().
 - Reorder the commits, putting the rename of self._args first.
 - Rebased.
Changes v4->v5:
 - Break the cleanup commit into logical changes and include in the
   commit messages the rationale for making them.
Changes v5->v6:
 - Remove the commit to rename self._args.
 - Fix is_running() return before first call to maunch().
 - Use python logging system.
 - Include the full command line on negative exit code error message.
 - Use os.path.null instead of /dev/null.
 - Improve the control over the created/deleted files.

Amador Pahim (7):
  qemu.py: use poll() instead of 'returncode'
  qemu.py: fix is_running() return before first launch()
  qemu.py: use python logging system
  qemu.py: improve message on negative exit code
  qemu.py: use os.path.null instead of /dev/null
  qemu.py: cleanup and improve launch()/shutdown()
  qemu.py: include debug information on launch error

 scripts/qemu.py | 121 ++++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 91 insertions(+), 30 deletions(-)

-- 
2.13.3

[Qemu-devel] [PATCH v6 1/7] qemu.py: use poll() instead of 'returncode'

[Amador Pahim]

The 'returncode' Popen attribute is not guaranteed to be updated. It
actually depends on a call to either poll(), wait() or communicate().

On the other hand, poll() will: "Check if child process has terminated.
Set and return returncode attribute."

Let's use the poll() to check whether the process is running and also
to get the updated process exit code, when the process is finished.

Signed-off-by: Amador Pahim <apahim@redhat.com>
Reviewed-by: Fam Zheng <famz@redhat.com>
Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/qemu.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/scripts/qemu.py b/scripts/qemu.py
index 880e3e8219..2f1984c93c 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -86,12 +86,12 @@ class QEMUMachine(object):
             raise
 
     def is_running(self):
-        return self._popen and (self._popen.returncode is None)
+        return self._popen and (self._popen.poll() is None)
 
     def exitcode(self):
         if self._popen is None:
             return None
-        return self._popen.returncode
+        return self._popen.poll()
 
     def get_pid(self):
         if not self.is_running():
-- 
2.13.3

[Qemu-devel] [PATCH v6 2/7] qemu.py: fix is_running() return before first launch()

[Amador Pahim]

is_running() returns None when called before the first time we
call launch():

    >>> import qemu
    >>> vm = qemu.QEMUMachine('qemu-system-x86_64')
    >>> vm.is_running()
    >>>

It should retunt False instead. This patch fixes that.

Signed-off-by: Amador Pahim <apahim@redhat.com>
---
 scripts/qemu.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/qemu.py b/scripts/qemu.py
index 2f1984c93c..77565eb092 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -86,7 +86,7 @@ class QEMUMachine(object):
             raise
 
     def is_running(self):
-        return self._popen and (self._popen.poll() is None)
+        return self._popen is not None and (self._popen.poll() is None)
 
     def exitcode(self):
         if self._popen is None:
-- 
2.13.3

[Qemu-devel] [PATCH v6 3/7] qemu.py: use python logging system

[Amador Pahim]

Let's provide extra control and flexibility by using python logging
system instead of print and/or sys.std*.write().

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

diff --git a/scripts/qemu.py b/scripts/qemu.py
index 77565eb092..e3ea534ec4 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -13,6 +13,7 @@
 #
 
 import errno
+import logging
 import string
 import os
 import sys
@@ -20,11 +21,19 @@ import subprocess
 import qmp.qmp
 
 
+logging.basicConfig()
+LOG = logging.getLogger(__name__)
+
+
 class QEMUMachine(object):
     '''A QEMU VM'''
 
     def __init__(self, binary, args=[], wrapper=[], name=None, test_dir="/var/tmp",
                  monitor_address=None, socket_scm_helper=None, debug=False):
+        if debug:
+            LOG.setLevel(logging.DEBUG)
+        else:
+            LOG.setLevel(logging.INFO)
         if name is None:
             name = "qemu-%d" % os.getpid()
         if monitor_address is None:
@@ -62,10 +71,10 @@ 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"
+            LOG.error("No path to socket_scm_helper set")
             return -1
         if os.path.exists(self._socket_scm_helper) == False:
-            print >>sys.stderr, "%s does not exist" % self._socket_scm_helper
+            LOG.error("%s does not exist", self._socket_scm_helper)
             return -1
         fd_param = ["%s" % self._socket_scm_helper,
                     "%d" % self._qmp.get_sock_fd(),
@@ -154,7 +163,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.error('qemu received signal %i: %s', -exitcode,
+                          ' '.join(self._args))
             self._load_io_log()
             self._post_shutdown()
 
-- 
2.13.3

[Qemu-devel] [PATCH v6 4/7] qemu.py: improve message on negative exit code

[Amador Pahim]

The current message shows 'self._args', which contains only part of the
options used in the qemu command line.

This patch makes the qemu full args list an instance variable and then
uses it in the negative exit code message.

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

diff --git a/scripts/qemu.py b/scripts/qemu.py
index e3ea534ec4..9434ccc30b 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -48,6 +48,7 @@ class QEMUMachine(object):
         self._iolog = None
         self._socket_scm_helper = socket_scm_helper
         self._debug = debug
+        self._qemu_full_args = None
 
     # This can be used to add an unused monitor instance.
     def add_monitor_telnet(self, ip, port):
@@ -140,9 +141,14 @@ class QEMUMachine(object):
         qemulog = open(self._qemu_log_path, 'wb')
         try:
             self._pre_launch()
-            args = self._wrapper + [self._binary] + self._base_args() + self._args
-            self._popen = subprocess.Popen(args, stdin=devnull, stdout=qemulog,
-                                           stderr=subprocess.STDOUT, shell=False)
+            self._qemu_full_args = None
+            self._qemu_full_args = (self._wrapper + [self._binary] +
+                                    self._base_args() + self._args)
+            self._popen = subprocess.Popen(self._qemu_full_args,
+                                           stdin=devnull,
+                                           stdout=qemulog,
+                                           stderr=subprocess.STDOUT,
+                                           shell=False)
             self._post_launch()
         except:
             if self.is_running():
@@ -163,8 +169,9 @@ class QEMUMachine(object):
 
             exitcode = self._popen.wait()
             if exitcode < 0:
-                LOG.error('qemu received signal %i: %s', -exitcode,
-                          ' '.join(self._args))
+                LOG.error('qemu received signal %i:%s', -exitcode,
+                          ' Command: %r.' % ' '.join(self._qemu_full_args)
+                          if self._qemu_full_args else '')
             self._load_io_log()
             self._post_shutdown()
 
-- 
2.13.3

[Qemu-devel] [PATCH v6 5/7] qemu.py: use os.path.null instead of /dev/null

[Amador Pahim]

For increased portability, let's use os.path.devnull.

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

diff --git a/scripts/qemu.py b/scripts/qemu.py
index 9434ccc30b..d313c6d4db 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -80,7 +80,7 @@ class QEMUMachine(object):
         fd_param = ["%s" % self._socket_scm_helper,
                     "%d" % self._qmp.get_sock_fd(),
                     "%s" % fd_file_path]
-        devnull = open('/dev/null', 'rb')
+        devnull = open(os.path.devnull, 'rb')
         p = subprocess.Popen(fd_param, stdin=devnull, stdout=sys.stdout,
                              stderr=sys.stderr)
         return p.wait()
@@ -137,7 +137,7 @@ class QEMUMachine(object):
 
     def launch(self):
         '''Launch the VM and establish a QMP connection'''
-        devnull = open('/dev/null', 'rb')
+        devnull = open(os.path.devnull, 'rb')
         qemulog = open(self._qemu_log_path, 'wb')
         try:
             self._pre_launch()
-- 
2.13.3

[Qemu-devel] [PATCH v6 6/7] qemu.py: cleanup and improve launch()/shutdown()

[Amador Pahim]

launch() is currently taking care of a number of flows, each one if its
own exception treatment, depending on the VM state and the files
creation state.

This patch makes launch() more resilient, off-loading the core calls to
the new _launch() and calling shutdown() if any exception is raised by
_launch(), making sure VM will be terminated and cleaned up.

Also, the pre_launch() was changed to make sure the files that will
be created are not present in the system before creating them and the
post_shutdown() will now only remove files that were created by this
instance.

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

diff --git a/scripts/qemu.py b/scripts/qemu.py
index d313c6d4db..e9a3a96d13 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -25,6 +25,10 @@ logging.basicConfig()
 LOG = logging.getLogger(__name__)
 
 
+class QEMULaunchError(Exception):
+    pass
+
+
 class QEMUMachine(object):
     '''A QEMU VM'''
 
@@ -40,6 +44,7 @@ class QEMUMachine(object):
             monitor_address = os.path.join(test_dir, name + "-monitor.sock")
         self._monitor_address = monitor_address
         self._qemu_log_path = os.path.join(test_dir, name + ".log")
+        self._qemu_log_fd = None
         self._popen = None
         self._binary = binary
         self._args = list(args) # Force copy args in case we modify them
@@ -49,6 +54,8 @@ class QEMUMachine(object):
         self._socket_scm_helper = socket_scm_helper
         self._debug = debug
         self._qemu_full_args = None
+        self._created_files = []
+        self._pending_shutdown = False
 
     # This can be used to add an unused monitor instance.
     def add_monitor_telnet(self, ip, port):
@@ -109,8 +116,9 @@ class QEMUMachine(object):
         return self._popen.pid
 
     def _load_io_log(self):
-        with open(self._qemu_log_path, "r") as fh:
-            self._iolog = fh.read()
+        if os.path.exists(self._qemu_log_path):
+            with open(self._qemu_log_path, "r") as fh:
+                self._iolog = fh.read()
 
     def _base_args(self):
         if isinstance(self._monitor_address, tuple):
@@ -124,40 +132,62 @@ class QEMUMachine(object):
                 '-display', 'none', '-vga', 'none']
 
     def _pre_launch(self):
-        self._qmp = qmp.qmp.QEMUMonitorProtocol(self._monitor_address, server=True,
+        if (not isinstance(self._monitor_address, tuple) and
+                os.path.exists(self._monitor_address)):
+            raise QEMULaunchError('File %s exists. Please remove it.' %
+                                  self._monitor_address)
+
+        self._qmp = qmp.qmp.QEMUMonitorProtocol(self._monitor_address,
+                                                server=True,
                                                 debug=self._debug)
+        if not isinstance(self._monitor_address, tuple):
+            self._created_files.append(self._monitor_address)
+
+        if os.path.exists(self._qemu_log_path):
+            raise QEMULaunchError('File %s exists. Please remove it.' %
+                                  self._qemu_log_path)
+
+        self._qemu_log_fd = open(self._qemu_log_path, 'wb')
+        self._created_files.append(self._qemu_log_path)
 
     def _post_launch(self):
         self._qmp.accept()
 
     def _post_shutdown(self):
-        if not isinstance(self._monitor_address, tuple):
-            self._remove_if_exists(self._monitor_address)
-        self._remove_if_exists(self._qemu_log_path)
+        while self._created_files:
+            self._remove_if_exists(self._created_files.pop())
 
     def launch(self):
         '''Launch the VM and establish a QMP connection'''
-        devnull = open(os.path.devnull, 'rb')
-        qemulog = open(self._qemu_log_path, 'wb')
+
+        if self.is_running():
+            raise QEMULaunchError('VM already running.')
+
+        if self._pending_shutdown:
+            raise QEMULaunchError('Shutdown after the previous launch '
+                                  'is pending. Please call shutdown() '
+                                  'before launching again.')
+
         try:
-            self._pre_launch()
             self._qemu_full_args = None
             self._qemu_full_args = (self._wrapper + [self._binary] +
                                     self._base_args() + self._args)
-            self._popen = subprocess.Popen(self._qemu_full_args,
-                                           stdin=devnull,
-                                           stdout=qemulog,
-                                           stderr=subprocess.STDOUT,
-                                           shell=False)
-            self._post_launch()
+            self._launch()
+            self._pending_shutdown = True
         except:
-            if self.is_running():
-                self._popen.kill()
-                self._popen.wait()
-            self._load_io_log()
-            self._post_shutdown()
+            self.shutdown()
             raise
 
+    def _launch(self):
+        self._pre_launch()
+        devnull = open(os.path.devnull, 'rb')
+        self._popen = subprocess.Popen(self._qemu_full_args,
+                                       stdin=devnull,
+                                       stdout=self._qemu_log_fd,
+                                       stderr=subprocess.STDOUT,
+                                       shell=False)
+        self._post_launch()
+
     def shutdown(self):
         '''Terminate the VM and clean up'''
         if self.is_running():
@@ -166,14 +196,18 @@ class QEMUMachine(object):
                 self._qmp.close()
             except:
                 self._popen.kill()
+            self._popen.wait()
 
-            exitcode = self._popen.wait()
-            if exitcode < 0:
-                LOG.error('qemu received signal %i:%s', -exitcode,
+        if self._pending_shutdown:
+            exit_code = self.exitcode()
+            if exit_code is not None and exit_code < 0:
+                LOG.error('qemu received signal %i: %s', -exit_code,
                           ' Command: %r.' % ' '.join(self._qemu_full_args)
                           if self._qemu_full_args else '')
-            self._load_io_log()
-            self._post_shutdown()
+
+        self._load_io_log()
+        self._post_shutdown()
+        self._pending_shutdown = False
 
     underscore_to_dash = string.maketrans('_', '-')
     def qmp(self, cmd, conv_keys=True, **args):
-- 
2.13.3

[Qemu-devel] [PATCH v6 7/7] qemu.py: include debug information on launch error

[Amador Pahim]

When launching a VM, if an exception happens and the VM is not
initiated, it is useful to see the qemu command line that was executed
and the output of that command.

Before this patch:

    >>> import qemu
    >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
    >>> vm.launch()
    Traceback (most recent call last):
      File "<stdin>", line 1, in <module>
      File "qemu.py", line 175, in launch
        self._launch()
      File "qemu.py", line 189, in _launch
        self._post_launch()
      File "qemu.py", line 154, in _post_launch
        self._qmp.accept()
      File "qmp/qmp.py", line 145, in accept
        self.__sock, _ = self.__sock.accept()
      File "/usr/lib64/python2.7/socket.py", line 206, in accept
        sock, addr = self._sock.accept()
    socket.timeout: timed out
    >>>

After this patch:

    >>> import qemu
    >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
    >>> vm.launch()
    DEBUG:qemu:Error launching VM. Command: 'qemu-system-aarch64
    -chardev socket,id=mon,path=/var/tmp/qemu-5298-monitor.sock
    -mon chardev=mon,mode=control -display none -vga none'.
    Output: 'qemu-system-aarch64: No machine specified, and there
    is no default\nUse -machine help to list supported machines\n'.
    Traceback (most recent call last):
      File "<stdin>", line 1, in <module>
      File "qemu.py", line 175, in launch
        self._launch()
      File "qemu.py", line 189, in _launch
        self._post_launch()
      File "qemu.py", line 154, in _post_launch
        self._qmp.accept()
      File "qmp/qmp.py", line 145, in accept
        self.__sock, _ = self.__sock.accept()
      File "/usr/lib64/python2.7/socket.py", line 206, in accept
        sock, addr = self._sock.accept()
    socket.timeout: timed out
    >>>

Signed-off-by: Amador Pahim <apahim@redhat.com>
---
 scripts/qemu.py | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

diff --git a/scripts/qemu.py b/scripts/qemu.py
index e9a3a96d13..43fd0b072c 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -158,7 +158,10 @@ class QEMUMachine(object):
             self._remove_if_exists(self._created_files.pop())
 
     def launch(self):
-        '''Launch the VM and establish a QMP connection'''
+        '''
+        Try to launch the VM and make sure we cleanup and expose the
+        command line/output in case of exception.
+        '''
 
         if self.is_running():
             raise QEMULaunchError('VM already running.')
@@ -169,6 +172,7 @@ class QEMUMachine(object):
                                   'before launching again.')
 
         try:
+            self._iolog = None
             self._qemu_full_args = None
             self._qemu_full_args = (self._wrapper + [self._binary] +
                                     self._base_args() + self._args)
@@ -176,9 +180,15 @@ class QEMUMachine(object):
             self._pending_shutdown = True
         except:
             self.shutdown()
+            LOG.debug('Error launching VM.%s%s',
+                      ' Command: %r.' % ' '.join(self._qemu_full_args)
+                      if self._qemu_full_args else '',
+                      ' Output: %r.' % self._iolog
+                      if self._iolog else '')
             raise
 
     def _launch(self):
+        '''Launch the VM and establish a QMP connection.'''
         self._pre_launch()
         devnull = open(os.path.devnull, 'rb')
         self._popen = subprocess.Popen(self._qemu_full_args,
-- 
2.13.3

Re: [Qemu-devel] [PATCH v6 1/7] qemu.py: use poll() instead of 'returncode'

[Eduardo Habkost]

On Mon, Jul 31, 2017 at 10:51:04AM +0200, Amador Pahim wrote:
> The 'returncode' Popen attribute is not guaranteed to be updated. It
> actually depends on a call to either poll(), wait() or communicate().
> 
> On the other hand, poll() will: "Check if child process has terminated.
> Set and return returncode attribute."
> 
> Let's use the poll() to check whether the process is running and also
> to get the updated process exit code, when the process is finished.
> 
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> Reviewed-by: Fam Zheng <famz@redhat.com>
> Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

This breaks the current version of shutdown().  Assuming that
patch 6/7 will fix that (I didn't review patch 6/7 yet), this
needs to be moved to the end of the series.

-- 
Eduardo

Re: [Qemu-devel] [PATCH v6 3/7] qemu.py: use python logging system

[Eduardo Habkost]

On Mon, Jul 31, 2017 at 10:51:06AM +0200, Amador Pahim wrote:
> Let's provide extra control and flexibility by using python logging
> system instead of print and/or sys.std*.write().
> 
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> ---
>  scripts/qemu.py | 16 +++++++++++++---
>  1 file changed, 13 insertions(+), 3 deletions(-)
> 
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index 77565eb092..e3ea534ec4 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -13,6 +13,7 @@
>  #
>  
>  import errno
> +import logging
>  import string
>  import os
>  import sys
> @@ -20,11 +21,19 @@ import subprocess
>  import qmp.qmp
>  
>  
> +logging.basicConfig()

Please don't call logging.basicConfig() from a module, as this
will break scripts that already use logging.basicConfig().

This breaks the following:

  $ ./scripts/device-crash-test --debug /usr/bin/qemu-system-x86_64


> +LOG = logging.getLogger(__name__)
> +
> +
>  class QEMUMachine(object):
>      '''A QEMU VM'''
>  
>      def __init__(self, binary, args=[], wrapper=[], name=None, test_dir="/var/tmp",
>                   monitor_address=None, socket_scm_helper=None, debug=False):
> +        if debug:
> +            LOG.setLevel(logging.DEBUG)
> +        else:
> +            LOG.setLevel(logging.INFO)

This makes the debug argument for one QEMUMachine object affect
other QEMUMachine objects.

What about:
    self.logger = LOG.getChild(name)
    self.logger.setLevel(...)

But do we really need to support per-QEMUMachine verbosity
levels?  We could simply eliminate the 'debug' argument and let
scripts configure logging.

>          if name is None:
>              name = "qemu-%d" % os.getpid()
>          if monitor_address is None:
> @@ -62,10 +71,10 @@ 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"
> +            LOG.error("No path to socket_scm_helper set")
>              return -1
>          if os.path.exists(self._socket_scm_helper) == False:
> -            print >>sys.stderr, "%s does not exist" % self._socket_scm_helper
> +            LOG.error("%s does not exist", self._socket_scm_helper)
>              return -1
>          fd_param = ["%s" % self._socket_scm_helper,
>                      "%d" % self._qmp.get_sock_fd(),
> @@ -154,7 +163,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.error('qemu received signal %i: %s', -exitcode,
> +                          ' '.join(self._args))
>              self._load_io_log()
>              self._post_shutdown()
>  
> -- 
> 2.13.3
> 

-- 
Eduardo

Re: [Qemu-devel] [PATCH v6 3/7] qemu.py: use python logging system

[Amador Pahim]

On Mon, Jul 31, 2017 at 4:50 PM, Eduardo Habkost <ehabkost@redhat.com> wrote:
> On Mon, Jul 31, 2017 at 10:51:06AM +0200, Amador Pahim wrote:
>> Let's provide extra control and flexibility by using python logging
>> system instead of print and/or sys.std*.write().
>>
>> Signed-off-by: Amador Pahim <apahim@redhat.com>
>> ---
>>  scripts/qemu.py | 16 +++++++++++++---
>>  1 file changed, 13 insertions(+), 3 deletions(-)
>>
>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>> index 77565eb092..e3ea534ec4 100644
>> --- a/scripts/qemu.py
>> +++ b/scripts/qemu.py
>> @@ -13,6 +13,7 @@
>>  #
>>
>>  import errno
>> +import logging
>>  import string
>>  import os
>>  import sys
>> @@ -20,11 +21,19 @@ import subprocess
>>  import qmp.qmp
>>
>>
>> +logging.basicConfig()
>
> Please don't call logging.basicConfig() from a module, as this
> will break scripts that already use logging.basicConfig().

Sure, this is a leftover from my tests.

>
> This breaks the following:
>
>   $ ./scripts/device-crash-test --debug /usr/bin/qemu-system-x86_64
>
>
>> +LOG = logging.getLogger(__name__)
>> +
>> +
>>  class QEMUMachine(object):
>>      '''A QEMU VM'''
>>
>>      def __init__(self, binary, args=[], wrapper=[], name=None, test_dir="/var/tmp",
>>                   monitor_address=None, socket_scm_helper=None, debug=False):
>> +        if debug:
>> +            LOG.setLevel(logging.DEBUG)
>> +        else:
>> +            LOG.setLevel(logging.INFO)
>
> This makes the debug argument for one QEMUMachine object affect
> other QEMUMachine objects.
>
> What about:
>     self.logger = LOG.getChild(name)
>     self.logger.setLevel(...)
>
> But do we really need to support per-QEMUMachine verbosity
> levels?  We could simply eliminate the 'debug' argument and let
> scripts configure logging.

Ok, agreed.

>
>>          if name is None:
>>              name = "qemu-%d" % os.getpid()
>>          if monitor_address is None:
>> @@ -62,10 +71,10 @@ 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"
>> +            LOG.error("No path to socket_scm_helper set")
>>              return -1
>>          if os.path.exists(self._socket_scm_helper) == False:
>> -            print >>sys.stderr, "%s does not exist" % self._socket_scm_helper
>> +            LOG.error("%s does not exist", self._socket_scm_helper)
>>              return -1
>>          fd_param = ["%s" % self._socket_scm_helper,
>>                      "%d" % self._qmp.get_sock_fd(),
>> @@ -154,7 +163,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.error('qemu received signal %i: %s', -exitcode,
>> +                          ' '.join(self._args))
>>              self._load_io_log()
>>              self._post_shutdown()
>>
>> --
>> 2.13.3
>>
>
> --
> Eduardo

Re: [Qemu-devel] [PATCH v6 2/7] qemu.py: fix is_running() return before first launch()

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1058 bytes --]

On Mon, Jul 31, 2017 at 10:51:05AM +0200, Amador Pahim wrote:
> is_running() returns None when called before the first time we
> call launch():
> 
>     >>> import qemu
>     >>> vm = qemu.QEMUMachine('qemu-system-x86_64')
>     >>> vm.is_running()
>     >>>
> 
> It should retunt False instead. This patch fixes that.

s/retunt/return/

> 
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> ---
>  scripts/qemu.py | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index 2f1984c93c..77565eb092 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -86,7 +86,7 @@ class QEMUMachine(object):
>              raise
>  
>      def is_running(self):
> -        return self._popen and (self._popen.poll() is None)
> +        return self._popen is not None and (self._popen.poll() is None)

The parentheses are inconsistent:

  return (self._popen is not None) and (self._popen.poll() is None)

An alternative:

  return bool(self._popen and self._popen.poll())

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 455 bytes --]

Re: [Qemu-devel] [PATCH v6 5/7] qemu.py: use os.path.null instead of /dev/null

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 317 bytes --]

On Mon, Jul 31, 2017 at 10:51:08AM +0200, Amador Pahim wrote:
> For increased portability, let's use os.path.devnull.
> 
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> ---
>  scripts/qemu.py | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 455 bytes --]

Re: [Qemu-devel] [PATCH v6 2/7] qemu.py: fix is_running() return before first launch()

[Eduardo Habkost]

On Tue, Aug 01, 2017 at 11:09:25AM +0100, Stefan Hajnoczi wrote:
> On Mon, Jul 31, 2017 at 10:51:05AM +0200, Amador Pahim wrote:
> > is_running() returns None when called before the first time we
> > call launch():
> > 
> >     >>> import qemu
> >     >>> vm = qemu.QEMUMachine('qemu-system-x86_64')
> >     >>> vm.is_running()
> >     >>>
> > 
> > It should retunt False instead. This patch fixes that.
> 
> s/retunt/return/
> 
> > 
> > Signed-off-by: Amador Pahim <apahim@redhat.com>
> > ---
> >  scripts/qemu.py | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/scripts/qemu.py b/scripts/qemu.py
> > index 2f1984c93c..77565eb092 100644
> > --- a/scripts/qemu.py
> > +++ b/scripts/qemu.py
> > @@ -86,7 +86,7 @@ class QEMUMachine(object):
> >              raise
> >  
> >      def is_running(self):
> > -        return self._popen and (self._popen.poll() is None)
> > +        return self._popen is not None and (self._popen.poll() is None)
> 
> The parentheses are inconsistent:
> 
>   return (self._popen is not None) and (self._popen.poll() is None)
> 
> An alternative:
> 
>   return bool(self._popen and self._popen.poll())

is_running() should be True only if self._popen.poll() is None
(and not if it's 0), so the "self._popen.poll() is None" part is
necessary.


-- 
Eduardo

Re: [Qemu-devel] [PATCH v6 2/7] qemu.py: fix is_running() return before first launch()

[Amador Pahim]

On Tue, Aug 1, 2017 at 12:50 PM, Eduardo Habkost <ehabkost@redhat.com> wrote:
> On Tue, Aug 01, 2017 at 11:09:25AM +0100, Stefan Hajnoczi wrote:
>> On Mon, Jul 31, 2017 at 10:51:05AM +0200, Amador Pahim wrote:
>> > is_running() returns None when called before the first time we
>> > call launch():
>> >
>> >     >>> import qemu
>> >     >>> vm = qemu.QEMUMachine('qemu-system-x86_64')
>> >     >>> vm.is_running()
>> >     >>>
>> >
>> > It should retunt False instead. This patch fixes that.
>>
>> s/retunt/return/
>>

Ack

>> >
>> > Signed-off-by: Amador Pahim <apahim@redhat.com>
>> > ---
>> >  scripts/qemu.py | 2 +-
>> >  1 file changed, 1 insertion(+), 1 deletion(-)
>> >
>> > diff --git a/scripts/qemu.py b/scripts/qemu.py
>> > index 2f1984c93c..77565eb092 100644
>> > --- a/scripts/qemu.py
>> > +++ b/scripts/qemu.py
>> > @@ -86,7 +86,7 @@ class QEMUMachine(object):
>> >              raise
>> >
>> >      def is_running(self):
>> > -        return self._popen and (self._popen.poll() is None)
>> > +        return self._popen is not None and (self._popen.poll() is None)
>>
>> The parentheses are inconsistent:
>>
>>   return (self._popen is not None) and (self._popen.poll() is None)

Parentheses are not needed here. I can remove the other one, if you want.

>>
>> An alternative:
>>
>>   return bool(self._popen and self._popen.poll())
>
> is_running() should be True only if self._popen.poll() is None
> (and not if it's 0), so the "self._popen.poll() is None" part is
> necessary.

+1

>
>
> --
> Eduardo

Re: [Qemu-devel] [PATCH v6 2/7] qemu.py: fix is_running() return before first launch()

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1835 bytes --]

On Tue, Aug 01, 2017 at 02:56:55PM +0200, Amador Pahim wrote:
> On Tue, Aug 1, 2017 at 12:50 PM, Eduardo Habkost <ehabkost@redhat.com> wrote:
> > On Tue, Aug 01, 2017 at 11:09:25AM +0100, Stefan Hajnoczi wrote:
> >> On Mon, Jul 31, 2017 at 10:51:05AM +0200, Amador Pahim wrote:
> >> > is_running() returns None when called before the first time we
> >> > call launch():
> >> >
> >> >     >>> import qemu
> >> >     >>> vm = qemu.QEMUMachine('qemu-system-x86_64')
> >> >     >>> vm.is_running()
> >> >     >>>
> >> >
> >> > It should retunt False instead. This patch fixes that.
> >>
> >> s/retunt/return/
> >>
> 
> Ack
> 
> >> >
> >> > Signed-off-by: Amador Pahim <apahim@redhat.com>
> >> > ---
> >> >  scripts/qemu.py | 2 +-
> >> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >> >
> >> > diff --git a/scripts/qemu.py b/scripts/qemu.py
> >> > index 2f1984c93c..77565eb092 100644
> >> > --- a/scripts/qemu.py
> >> > +++ b/scripts/qemu.py
> >> > @@ -86,7 +86,7 @@ class QEMUMachine(object):
> >> >              raise
> >> >
> >> >      def is_running(self):
> >> > -        return self._popen and (self._popen.poll() is None)
> >> > +        return self._popen is not None and (self._popen.poll() is None)
> >>
> >> The parentheses are inconsistent:
> >>
> >>   return (self._popen is not None) and (self._popen.poll() is None)
> 
> Parentheses are not needed here. I can remove the other one, if you want.

That would be fine.  There are no other instances in the file and PEP8
doesn't cover this either.

> >>
> >> An alternative:
> >>
> >>   return bool(self._popen and self._popen.poll())
> >
> > is_running() should be True only if self._popen.poll() is None
> > (and not if it's 0), so the "self._popen.poll() is None" part is
> > necessary.
> 
> +1

oops :)

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 455 bytes --]

Re: [Qemu-devel] [PATCH v6 3/7] qemu.py: use python logging system

[Markus Armbruster]

Please spell "Python" with a capital "P" (it's a proper name).

Amador Pahim <apahim@redhat.com> writes:

> Let's provide extra control and flexibility by using python logging
> system instead of print and/or sys.std*.write().
>
> Signed-off-by: Amador Pahim <apahim@redhat.com>

How exactly does this change error messages?

Is logging the right tool to report errors to the human user?  I'm
asking because logging and error reporting are generally separate
things.  Example: a program runs into a recoverable error.  It logs the
error, but does not report it.

Is reporting errors to stderr the right thing to do for library class
QEMUMachine?  I doubt it.  Libraries throw exceptions and let their
users decide how to handle them.

Re: [Qemu-devel] [PATCH v6 4/7] qemu.py: improve message on negative exit code

[Markus Armbruster]

Amador Pahim <apahim@redhat.com> writes:

> The current message shows 'self._args', which contains only part of the
> options used in the qemu command line.
>
> This patch makes the qemu full args list an instance variable and then
> uses it in the negative exit code message.
>
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> ---
>  scripts/qemu.py | 17 ++++++++++++-----
>  1 file changed, 12 insertions(+), 5 deletions(-)
>
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index e3ea534ec4..9434ccc30b 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -48,6 +48,7 @@ class QEMUMachine(object):
>          self._iolog = None
>          self._socket_scm_helper = socket_scm_helper
>          self._debug = debug
> +        self._qemu_full_args = None
>  
>      # This can be used to add an unused monitor instance.
>      def add_monitor_telnet(self, ip, port):
> @@ -140,9 +141,14 @@ class QEMUMachine(object):
>          qemulog = open(self._qemu_log_path, 'wb')
>          try:
>              self._pre_launch()
> -            args = self._wrapper + [self._binary] + self._base_args() + self._args
> -            self._popen = subprocess.Popen(args, stdin=devnull, stdout=qemulog,
> -                                           stderr=subprocess.STDOUT, shell=False)
> +            self._qemu_full_args = None
> +            self._qemu_full_args = (self._wrapper + [self._binary] +
> +                                    self._base_args() + self._args)

Why set self._qemu_full_args twice?

> +            self._popen = subprocess.Popen(self._qemu_full_args,
> +                                           stdin=devnull,
> +                                           stdout=qemulog,
> +                                           stderr=subprocess.STDOUT,
> +                                           shell=False)
>              self._post_launch()
>          except:
>              if self.is_running():
> @@ -163,8 +169,9 @@ class QEMUMachine(object):
>  
>              exitcode = self._popen.wait()
>              if exitcode < 0:
> -                LOG.error('qemu received signal %i: %s', -exitcode,
> -                          ' '.join(self._args))
> +                LOG.error('qemu received signal %i:%s', -exitcode,
> +                          ' Command: %r.' % ' '.join(self._qemu_full_args)
> +                          if self._qemu_full_args else '')

The last argument is hard to read.

>              self._load_io_log()
>              self._post_shutdown()

The subprocess module appears to keep track of the full command with
methods check_call() and check_output(): its in exception
CalledProcessError right when you need it.  Sadly, it doesn't appear to
be tracked with method Popen().

Re: [Qemu-devel] [PATCH v6 6/7] qemu.py: cleanup and improve launch()/shutdown()

[Markus Armbruster]

Amador Pahim <apahim@redhat.com> writes:

> launch() is currently taking care of a number of flows, each one if its
> own exception treatment, depending on the VM state and the files
> creation state.
>
> This patch makes launch() more resilient, off-loading the core calls to
> the new _launch() and calling shutdown() if any exception is raised by
> _launch(), making sure VM will be terminated and cleaned up.
>
> Also, the pre_launch() was changed to make sure the files that will

Imperative mood, please: "change pre_launch() to make sure..."

"Also, ..." in a commit message is often a sign that the commit should
be split.  I'm not sure in this case, because I'm not yet sure I get
what it does.  Could also be a sign that it should be split :)

> be created are not present in the system before creating them and the
> post_shutdown() will now only remove files that were created by this
> instance.
>
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> ---
>  scripts/qemu.py | 84 ++++++++++++++++++++++++++++++++++++++++-----------------
>  1 file changed, 59 insertions(+), 25 deletions(-)
>
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index d313c6d4db..e9a3a96d13 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -25,6 +25,10 @@ logging.basicConfig()
>  LOG = logging.getLogger(__name__)
>  
>  
> +class QEMULaunchError(Exception):
> +    pass
> +
> +
>  class QEMUMachine(object):
>      '''A QEMU VM'''
>  
> @@ -40,6 +44,7 @@ class QEMUMachine(object):
>              monitor_address = os.path.join(test_dir, name + "-monitor.sock")
>          self._monitor_address = monitor_address
>          self._qemu_log_path = os.path.join(test_dir, name + ".log")
> +        self._qemu_log_fd = None
>          self._popen = None
>          self._binary = binary
>          self._args = list(args) # Force copy args in case we modify them
> @@ -49,6 +54,8 @@ class QEMUMachine(object):
>          self._socket_scm_helper = socket_scm_helper
>          self._debug = debug
>          self._qemu_full_args = None
> +        self._created_files = []
> +        self._pending_shutdown = False
>  
>      # This can be used to add an unused monitor instance.
>      def add_monitor_telnet(self, ip, port):
> @@ -109,8 +116,9 @@ class QEMUMachine(object):
>          return self._popen.pid
>  
>      def _load_io_log(self):
> -        with open(self._qemu_log_path, "r") as fh:
> -            self._iolog = fh.read()
> +        if os.path.exists(self._qemu_log_path):
> +            with open(self._qemu_log_path, "r") as fh:
> +                self._iolog = fh.read()

The new conditional predicts whether open() will fail with ENOENT.
Trying to predict failure is generally a bad idea.  What if some other
process removes ._qemu_log_path between .exists() and open()?  You're
better off catching the exception from open().

>  
>      def _base_args(self):
>          if isinstance(self._monitor_address, tuple):
> @@ -124,40 +132,62 @@ class QEMUMachine(object):
>                  '-display', 'none', '-vga', 'none']
>  
>      def _pre_launch(self):
> -        self._qmp = qmp.qmp.QEMUMonitorProtocol(self._monitor_address, server=True,
> +        if (not isinstance(self._monitor_address, tuple) and
> +                os.path.exists(self._monitor_address)):
> +            raise QEMULaunchError('File %s exists. Please remove it.' %
> +                                  self._monitor_address)

What if some other process creates ._monitor_address between .exists()
and the bind() in QEMUMonitorProtocol.__init__()?

See, .exists() is almost always wrong.

> +
> +        self._qmp = qmp.qmp.QEMUMonitorProtocol(self._monitor_address,
> +                                                server=True,
>                                                  debug=self._debug)
> +        if not isinstance(self._monitor_address, tuple):
> +            self._created_files.append(self._monitor_address)
> +
> +        if os.path.exists(self._qemu_log_path):
> +            raise QEMULaunchError('File %s exists. Please remove it.' %
> +                                  self._qemu_log_path)

Likewise.

> +
> +        self._qemu_log_fd = open(self._qemu_log_path, 'wb')
> +        self._created_files.append(self._qemu_log_path)
>  
>      def _post_launch(self):
>          self._qmp.accept()
>  
>      def _post_shutdown(self):
> -        if not isinstance(self._monitor_address, tuple):
> -            self._remove_if_exists(self._monitor_address)
> -        self._remove_if_exists(self._qemu_log_path)
> +        while self._created_files:
> +            self._remove_if_exists(self._created_files.pop())
>  
>      def launch(self):
>          '''Launch the VM and establish a QMP connection'''
> -        devnull = open(os.path.devnull, 'rb')
> -        qemulog = open(self._qemu_log_path, 'wb')
> +
> +        if self.is_running():
> +            raise QEMULaunchError('VM already running.')

Drop the period, please.

> +
> +        if self._pending_shutdown:
> +            raise QEMULaunchError('Shutdown after the previous launch '
> +                                  'is pending. Please call shutdown() '
> +                                  'before launching again.')

Single phrase describing the error, please.

> +
>          try:
> -            self._pre_launch()
>              self._qemu_full_args = None
>              self._qemu_full_args = (self._wrapper + [self._binary] +
>                                      self._base_args() + self._args)
> -            self._popen = subprocess.Popen(self._qemu_full_args,
> -                                           stdin=devnull,
> -                                           stdout=qemulog,
> -                                           stderr=subprocess.STDOUT,
> -                                           shell=False)
> -            self._post_launch()
> +            self._launch()
> +            self._pending_shutdown = True
>          except:
> -            if self.is_running():
> -                self._popen.kill()
> -                self._popen.wait()
> -            self._load_io_log()
> -            self._post_shutdown()
> +            self.shutdown()
>              raise
>  
> +    def _launch(self):
> +        self._pre_launch()
> +        devnull = open(os.path.devnull, 'rb')
> +        self._popen = subprocess.Popen(self._qemu_full_args,
> +                                       stdin=devnull,
> +                                       stdout=self._qemu_log_fd,
> +                                       stderr=subprocess.STDOUT,
> +                                       shell=False)
> +        self._post_launch()
> +
>      def shutdown(self):
>          '''Terminate the VM and clean up'''
>          if self.is_running():
> @@ -166,14 +196,18 @@ class QEMUMachine(object):
>                  self._qmp.close()
>              except:
>                  self._popen.kill()
> +            self._popen.wait()
>  
> -            exitcode = self._popen.wait()
> -            if exitcode < 0:
> -                LOG.error('qemu received signal %i:%s', -exitcode,
> +        if self._pending_shutdown:
> +            exit_code = self.exitcode()
> +            if exit_code is not None and exit_code < 0:
> +                LOG.error('qemu received signal %i: %s', -exit_code,
>                            ' Command: %r.' % ' '.join(self._qemu_full_args)
>                            if self._qemu_full_args else '')
> -            self._load_io_log()
> -            self._post_shutdown()
> +
> +        self._load_io_log()
> +        self._post_shutdown()
> +        self._pending_shutdown = False
>  
>      underscore_to_dash = string.maketrans('_', '-')
>      def qmp(self, cmd, conv_keys=True, **args):

Re: [Qemu-devel] [PATCH v6 7/7] qemu.py: include debug information on launch error

[Markus Armbruster]

Amador Pahim <apahim@redhat.com> writes:

> When launching a VM, if an exception happens and the VM is not
> initiated, it is useful to see the qemu command line that was executed
> and the output of that command.
>
> Before this patch:
>
>     >>> import qemu
>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>     >>> vm.launch()
>     Traceback (most recent call last):
>       File "<stdin>", line 1, in <module>
>       File "qemu.py", line 175, in launch
>         self._launch()
>       File "qemu.py", line 189, in _launch
>         self._post_launch()
>       File "qemu.py", line 154, in _post_launch
>         self._qmp.accept()
>       File "qmp/qmp.py", line 145, in accept
>         self.__sock, _ = self.__sock.accept()
>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>         sock, addr = self._sock.accept()
>     socket.timeout: timed out
>     >>>
>
> After this patch:
>
>     >>> import qemu
>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>     >>> vm.launch()
>     DEBUG:qemu:Error launching VM. Command: 'qemu-system-aarch64
>     -chardev socket,id=mon,path=/var/tmp/qemu-5298-monitor.sock
>     -mon chardev=mon,mode=control -display none -vga none'.
>     Output: 'qemu-system-aarch64: No machine specified, and there
>     is no default\nUse -machine help to list supported machines\n'.
>     Traceback (most recent call last):
>       File "<stdin>", line 1, in <module>
>       File "qemu.py", line 175, in launch
>         self._launch()
>       File "qemu.py", line 189, in _launch
>         self._post_launch()
>       File "qemu.py", line 154, in _post_launch
>         self._qmp.accept()
>       File "qmp/qmp.py", line 145, in accept
>         self.__sock, _ = self.__sock.accept()
>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>         sock, addr = self._sock.accept()
>     socket.timeout: timed out
>     >>>
>
> Signed-off-by: Amador Pahim <apahim@redhat.com>
> ---
>  scripts/qemu.py | 12 +++++++++++-
>  1 file changed, 11 insertions(+), 1 deletion(-)
>
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index e9a3a96d13..43fd0b072c 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -158,7 +158,10 @@ class QEMUMachine(object):
>              self._remove_if_exists(self._created_files.pop())
>  
>      def launch(self):
> -        '''Launch the VM and establish a QMP connection'''
> +        '''
> +        Try to launch the VM and make sure we cleanup and expose the
> +        command line/output in case of exception.
> +        '''
>  
>          if self.is_running():
>              raise QEMULaunchError('VM already running.')
> @@ -169,6 +172,7 @@ class QEMUMachine(object):
>                                    'before launching again.')
>  
>          try:
> +            self._iolog = None
>              self._qemu_full_args = None
>              self._qemu_full_args = (self._wrapper + [self._binary] +
>                                      self._base_args() + self._args)
> @@ -176,9 +180,15 @@ class QEMUMachine(object):
>              self._pending_shutdown = True
>          except:
>              self.shutdown()
> +            LOG.debug('Error launching VM.%s%s',
> +                      ' Command: %r.' % ' '.join(self._qemu_full_args)
> +                      if self._qemu_full_args else '',
> +                      ' Output: %r.' % self._iolog
> +                      if self._iolog else '')

This nested interpolation is too ugly to live :)

Nesting is easy to avoid:

               LOG.debug('Error launching VM\n. ' Command: %r. Output: %r.'
                         % (' '.join(self._qemu_full_args)
                            if self._qemu_full_args else '',
                            self._iolog
                            if self._iolog else ''))

Why %r and not %s?

Are you sure '\n' is appropriate in the argument of LOG.debug()?

Why cram everything into a single LOG.debug()?

               LOG.debug('Error launching VM')
               LOG.debug('Command: %s' % (' '.join(self._qemu_full_args)
                                          if self._qemu_full_args else ''))
               LOG.debug('Output: %s' % self._iolog if self._iolog else ''))

>              raise
>  
>      def _launch(self):
> +        '''Launch the VM and establish a QMP connection.'''
>          self._pre_launch()
>          devnull = open(os.path.devnull, 'rb')
>          self._popen = subprocess.Popen(self._qemu_full_args,

Re: [Qemu-devel] [PATCH v6 3/7] qemu.py: use python logging system

[Eduardo Habkost]

On Tue, Aug 15, 2017 at 10:10:12AM +0200, Markus Armbruster wrote:
> Please spell "Python" with a capital "P" (it's a proper name).
> 
> Amador Pahim <apahim@redhat.com> writes:
> 
> > Let's provide extra control and flexibility by using python logging
> > system instead of print and/or sys.std*.write().
> >
> > Signed-off-by: Amador Pahim <apahim@redhat.com>
> 
> How exactly does this change error messages?
> 
> Is logging the right tool to report errors to the human user?  I'm
> asking because logging and error reporting are generally separate
> things.  Example: a program runs into a recoverable error.  It logs the
> error, but does not report it.
> 
> Is reporting errors to stderr the right thing to do for library class
> QEMUMachine?  I doubt it.  Libraries throw exceptions and let their
> users decide how to handle them.

I believe the "qemu received signal" event is supposed to be
logged, not necessarily reported.  Callers can then choose where
the log messages should go (scripts could choose to send them
directly to stderr if verbose or debugging mode is enabled).  We
don't even need an exception for it: we can let callers check
exitcode() and decide what to do about the QEMU exit code.

The send_fd_scm() messages, on the other hand, could become
exceptions, and don't need the logging system at all.

-- 
Eduardo

Re: [Qemu-devel] [PATCH v6 3/7] qemu.py: use python logging system

[Markus Armbruster]

Eduardo Habkost <ehabkost@redhat.com> writes:

> On Tue, Aug 15, 2017 at 10:10:12AM +0200, Markus Armbruster wrote:
>> Please spell "Python" with a capital "P" (it's a proper name).
>> 
>> Amador Pahim <apahim@redhat.com> writes:
>> 
>> > Let's provide extra control and flexibility by using python logging
>> > system instead of print and/or sys.std*.write().
>> >
>> > Signed-off-by: Amador Pahim <apahim@redhat.com>
>> 
>> How exactly does this change error messages?
>> 
>> Is logging the right tool to report errors to the human user?  I'm
>> asking because logging and error reporting are generally separate
>> things.  Example: a program runs into a recoverable error.  It logs the
>> error, but does not report it.
>> 
>> Is reporting errors to stderr the right thing to do for library class
>> QEMUMachine?  I doubt it.  Libraries throw exceptions and let their
>> users decide how to handle them.
>
> I believe the "qemu received signal" event is supposed to be
> logged, not necessarily reported.  Callers can then choose where
> the log messages should go (scripts could choose to send them
> directly to stderr if verbose or debugging mode is enabled).  We
> don't even need an exception for it: we can let callers check
> exitcode() and decide what to do about the QEMU exit code.

Makes sense.

> The send_fd_scm() messages, on the other hand, could become
> exceptions, and don't need the logging system at all.

I think we all agree that printing to stderr is not a good idea for this
library class.  Instead of a blanket conversion to logging without
further explanation, I'd like to see cleanup with rationale such as
yours.

Re: [Qemu-devel] [PATCH v6 4/7] qemu.py: improve message on negative exit code

[Amador Pahim]

On Tue, Aug 15, 2017 at 10:26 AM, Markus Armbruster <armbru@redhat.com> wrote:
> Amador Pahim <apahim@redhat.com> writes:
>
>> The current message shows 'self._args', which contains only part of the
>> options used in the qemu command line.
>>
>> This patch makes the qemu full args list an instance variable and then
>> uses it in the negative exit code message.
>>
>> Signed-off-by: Amador Pahim <apahim@redhat.com>
>> ---
>>  scripts/qemu.py | 17 ++++++++++++-----
>>  1 file changed, 12 insertions(+), 5 deletions(-)
>>
>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>> index e3ea534ec4..9434ccc30b 100644
>> --- a/scripts/qemu.py
>> +++ b/scripts/qemu.py
>> @@ -48,6 +48,7 @@ class QEMUMachine(object):
>>          self._iolog = None
>>          self._socket_scm_helper = socket_scm_helper
>>          self._debug = debug
>> +        self._qemu_full_args = None
>>
>>      # This can be used to add an unused monitor instance.
>>      def add_monitor_telnet(self, ip, port):
>> @@ -140,9 +141,14 @@ class QEMUMachine(object):
>>          qemulog = open(self._qemu_log_path, 'wb')
>>          try:
>>              self._pre_launch()
>> -            args = self._wrapper + [self._binary] + self._base_args() + self._args
>> -            self._popen = subprocess.Popen(args, stdin=devnull, stdout=qemulog,
>> -                                           stderr=subprocess.STDOUT, shell=False)
>> +            self._qemu_full_args = None
>> +            self._qemu_full_args = (self._wrapper + [self._binary] +
>> +                                    self._base_args() + self._args)
>
> Why set self._qemu_full_args twice?

If it's not cleaned up and an exception happens in
"self._qemu_full_args = (self._wrapper ...", the message logged in the
"except" will expose an outdated version of it.

>
>> +            self._popen = subprocess.Popen(self._qemu_full_args,
>> +                                           stdin=devnull,
>> +                                           stdout=qemulog,
>> +                                           stderr=subprocess.STDOUT,
>> +                                           shell=False)
>>              self._post_launch()
>>          except:
>>              if self.is_running():
>> @@ -163,8 +169,9 @@ class QEMUMachine(object):
>>
>>              exitcode = self._popen.wait()
>>              if exitcode < 0:
>> -                LOG.error('qemu received signal %i: %s', -exitcode,
>> -                          ' '.join(self._args))
>> +                LOG.error('qemu received signal %i:%s', -exitcode,
>> +                          ' Command: %r.' % ' '.join(self._qemu_full_args)
>> +                          if self._qemu_full_args else '')
>
> The last argument is hard to read.

Ok, I'm making it easier.

>
>>              self._load_io_log()
>>              self._post_shutdown()
>
> The subprocess module appears to keep track of the full command with
> methods check_call() and check_output(): its in exception
> CalledProcessError right when you need it.  Sadly, it doesn't appear to
> be tracked with method Popen().

Indeed.

Re: [Qemu-devel] [PATCH v6 3/7] qemu.py: use python logging system

[Amador Pahim]

On Wed, Aug 16, 2017 at 8:17 AM, Markus Armbruster <armbru@redhat.com> wrote:
> Eduardo Habkost <ehabkost@redhat.com> writes:
>
>> On Tue, Aug 15, 2017 at 10:10:12AM +0200, Markus Armbruster wrote:
>>> Please spell "Python" with a capital "P" (it's a proper name).
>>>
>>> Amador Pahim <apahim@redhat.com> writes:
>>>
>>> > Let's provide extra control and flexibility by using python logging
>>> > system instead of print and/or sys.std*.write().
>>> >
>>> > Signed-off-by: Amador Pahim <apahim@redhat.com>
>>>
>>> How exactly does this change error messages?
>>>
>>> Is logging the right tool to report errors to the human user?  I'm
>>> asking because logging and error reporting are generally separate
>>> things.  Example: a program runs into a recoverable error.  It logs the
>>> error, but does not report it.
>>>
>>> Is reporting errors to stderr the right thing to do for library class
>>> QEMUMachine?  I doubt it.  Libraries throw exceptions and let their
>>> users decide how to handle them.
>>
>> I believe the "qemu received signal" event is supposed to be
>> logged, not necessarily reported.  Callers can then choose where
>> the log messages should go (scripts could choose to send them
>> directly to stderr if verbose or debugging mode is enabled).  We
>> don't even need an exception for it: we can let callers check
>> exitcode() and decide what to do about the QEMU exit code.
>
> Makes sense.
>
>> The send_fd_scm() messages, on the other hand, could become
>> exceptions, and don't need the logging system at all.
>
> I think we all agree that printing to stderr is not a good idea for this
> library class.  Instead of a blanket conversion to logging without
> further explanation, I'd like to see cleanup with rationale such as
> yours.

Ok.

Re: [Qemu-devel] [PATCH v6 7/7] qemu.py: include debug information on launch error

[Amador Pahim]

On Tue, Aug 15, 2017 at 10:57 AM, Markus Armbruster <armbru@redhat.com> wrote:
> Amador Pahim <apahim@redhat.com> writes:
>
>> When launching a VM, if an exception happens and the VM is not
>> initiated, it is useful to see the qemu command line that was executed
>> and the output of that command.
>>
>> Before this patch:
>>
>>     >>> import qemu
>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>     >>> vm.launch()
>>     Traceback (most recent call last):
>>       File "<stdin>", line 1, in <module>
>>       File "qemu.py", line 175, in launch
>>         self._launch()
>>       File "qemu.py", line 189, in _launch
>>         self._post_launch()
>>       File "qemu.py", line 154, in _post_launch
>>         self._qmp.accept()
>>       File "qmp/qmp.py", line 145, in accept
>>         self.__sock, _ = self.__sock.accept()
>>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>>         sock, addr = self._sock.accept()
>>     socket.timeout: timed out
>>     >>>
>>
>> After this patch:
>>
>>     >>> import qemu
>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>     >>> vm.launch()
>>     DEBUG:qemu:Error launching VM. Command: 'qemu-system-aarch64
>>     -chardev socket,id=mon,path=/var/tmp/qemu-5298-monitor.sock
>>     -mon chardev=mon,mode=control -display none -vga none'.
>>     Output: 'qemu-system-aarch64: No machine specified, and there
>>     is no default\nUse -machine help to list supported machines\n'.
>>     Traceback (most recent call last):
>>       File "<stdin>", line 1, in <module>
>>       File "qemu.py", line 175, in launch
>>         self._launch()
>>       File "qemu.py", line 189, in _launch
>>         self._post_launch()
>>       File "qemu.py", line 154, in _post_launch
>>         self._qmp.accept()
>>       File "qmp/qmp.py", line 145, in accept
>>         self.__sock, _ = self.__sock.accept()
>>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>>         sock, addr = self._sock.accept()
>>     socket.timeout: timed out
>>     >>>
>>
>> Signed-off-by: Amador Pahim <apahim@redhat.com>
>> ---
>>  scripts/qemu.py | 12 +++++++++++-
>>  1 file changed, 11 insertions(+), 1 deletion(-)
>>
>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>> index e9a3a96d13..43fd0b072c 100644
>> --- a/scripts/qemu.py
>> +++ b/scripts/qemu.py
>> @@ -158,7 +158,10 @@ class QEMUMachine(object):
>>              self._remove_if_exists(self._created_files.pop())
>>
>>      def launch(self):
>> -        '''Launch the VM and establish a QMP connection'''
>> +        '''
>> +        Try to launch the VM and make sure we cleanup and expose the
>> +        command line/output in case of exception.
>> +        '''
>>
>>          if self.is_running():
>>              raise QEMULaunchError('VM already running.')
>> @@ -169,6 +172,7 @@ class QEMUMachine(object):
>>                                    'before launching again.')
>>
>>          try:
>> +            self._iolog = None
>>              self._qemu_full_args = None
>>              self._qemu_full_args = (self._wrapper + [self._binary] +
>>                                      self._base_args() + self._args)
>> @@ -176,9 +180,15 @@ class QEMUMachine(object):
>>              self._pending_shutdown = True
>>          except:
>>              self.shutdown()
>> +            LOG.debug('Error launching VM.%s%s',
>> +                      ' Command: %r.' % ' '.join(self._qemu_full_args)
>> +                      if self._qemu_full_args else '',
>> +                      ' Output: %r.' % self._iolog
>> +                      if self._iolog else '')
>
> This nested interpolation is too ugly to live :)

I find it beautiful :)
Killing it anyway.

>
> Nesting is easy to avoid:
>
>                LOG.debug('Error launching VM\n. ' Command: %r. Output: %r.'
>                          % (' '.join(self._qemu_full_args)
>                             if self._qemu_full_args else '',
>                             self._iolog
>                             if self._iolog else ''))

In this case we will have the strings "Command: " and "Output:" even
with no content to expose.

>
> Why %r and not %s?

It's a matter of preference. I tend to avoid allowing messages to
break the log line. Anyway, I'm improving this.

>
> Are you sure '\n' is appropriate in the argument of LOG.debug()?
>
> Why cram everything into a single LOG.debug()?
>
>                LOG.debug('Error launching VM')
>                LOG.debug('Command: %s' % (' '.join(self._qemu_full_args)
>                                           if self._qemu_full_args else ''))
>                LOG.debug('Output: %s' % self._iolog if self._iolog else ''))

Sure, I'm ok with both ways.

>
>>              raise
>>
>>      def _launch(self):
>> +        '''Launch the VM and establish a QMP connection.'''
>>          self._pre_launch()
>>          devnull = open(os.path.devnull, 'rb')
>>          self._popen = subprocess.Popen(self._qemu_full_args,

Re: [Qemu-devel] [PATCH v6 4/7] qemu.py: improve message on negative exit code

[Markus Armbruster]

Amador Pahim <apahim@redhat.com> writes:

> On Tue, Aug 15, 2017 at 10:26 AM, Markus Armbruster <armbru@redhat.com> wrote:
>> Amador Pahim <apahim@redhat.com> writes:
>>
>>> The current message shows 'self._args', which contains only part of the
>>> options used in the qemu command line.
>>>
>>> This patch makes the qemu full args list an instance variable and then
>>> uses it in the negative exit code message.
>>>
>>> Signed-off-by: Amador Pahim <apahim@redhat.com>
>>> ---
>>>  scripts/qemu.py | 17 ++++++++++++-----
>>>  1 file changed, 12 insertions(+), 5 deletions(-)
>>>
>>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>>> index e3ea534ec4..9434ccc30b 100644
>>> --- a/scripts/qemu.py
>>> +++ b/scripts/qemu.py
>>> @@ -48,6 +48,7 @@ class QEMUMachine(object):
>>>          self._iolog = None
>>>          self._socket_scm_helper = socket_scm_helper
>>>          self._debug = debug
>>> +        self._qemu_full_args = None
>>>
>>>      # This can be used to add an unused monitor instance.
>>>      def add_monitor_telnet(self, ip, port):
>>> @@ -140,9 +141,14 @@ class QEMUMachine(object):
>>>          qemulog = open(self._qemu_log_path, 'wb')
>>>          try:
>>>              self._pre_launch()
>>> -            args = self._wrapper + [self._binary] + self._base_args() + self._args
>>> -            self._popen = subprocess.Popen(args, stdin=devnull, stdout=qemulog,
>>> -                                           stderr=subprocess.STDOUT, shell=False)
>>> +            self._qemu_full_args = None
>>> +            self._qemu_full_args = (self._wrapper + [self._binary] +
>>> +                                    self._base_args() + self._args)
>>
>> Why set self._qemu_full_args twice?
>
> If it's not cleaned up and an exception happens in
> "self._qemu_full_args = (self._wrapper ...", the message logged in the
> "except" will expose an outdated version of it.

Ignorant question: why aren't we cleaning it up?

>>> +            self._popen = subprocess.Popen(self._qemu_full_args,
>>> +                                           stdin=devnull,
>>> +                                           stdout=qemulog,
>>> +                                           stderr=subprocess.STDOUT,
>>> +                                           shell=False)
>>>              self._post_launch()
>>>          except:
>>>              if self.is_running():
>>> @@ -163,8 +169,9 @@ class QEMUMachine(object):
>>>
>>>              exitcode = self._popen.wait()
>>>              if exitcode < 0:
>>> -                LOG.error('qemu received signal %i: %s', -exitcode,
>>> -                          ' '.join(self._args))
>>> +                LOG.error('qemu received signal %i:%s', -exitcode,
>>> +                          ' Command: %r.' % ' '.join(self._qemu_full_args)
>>> +                          if self._qemu_full_args else '')
>>
>> The last argument is hard to read.
>
> Ok, I'm making it easier.
>
>>
>>>              self._load_io_log()
>>>              self._post_shutdown()
>>
>> The subprocess module appears to keep track of the full command with
>> methods check_call() and check_output(): its in exception
>> CalledProcessError right when you need it.  Sadly, it doesn't appear to
>> be tracked with method Popen().
>
> Indeed.

Re: [Qemu-devel] [PATCH v6 7/7] qemu.py: include debug information on launch error

[Markus Armbruster]

Amador Pahim <apahim@redhat.com> writes:

> On Tue, Aug 15, 2017 at 10:57 AM, Markus Armbruster <armbru@redhat.com> wrote:
>> Amador Pahim <apahim@redhat.com> writes:
>>
>>> When launching a VM, if an exception happens and the VM is not
>>> initiated, it is useful to see the qemu command line that was executed
>>> and the output of that command.
>>>
>>> Before this patch:
>>>
>>>     >>> import qemu
>>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>>     >>> vm.launch()
>>>     Traceback (most recent call last):
>>>       File "<stdin>", line 1, in <module>
>>>       File "qemu.py", line 175, in launch
>>>         self._launch()
>>>       File "qemu.py", line 189, in _launch
>>>         self._post_launch()
>>>       File "qemu.py", line 154, in _post_launch
>>>         self._qmp.accept()
>>>       File "qmp/qmp.py", line 145, in accept
>>>         self.__sock, _ = self.__sock.accept()
>>>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>>>         sock, addr = self._sock.accept()
>>>     socket.timeout: timed out
>>>     >>>
>>>
>>> After this patch:
>>>
>>>     >>> import qemu
>>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>>     >>> vm.launch()
>>>     DEBUG:qemu:Error launching VM. Command: 'qemu-system-aarch64
>>>     -chardev socket,id=mon,path=/var/tmp/qemu-5298-monitor.sock
>>>     -mon chardev=mon,mode=control -display none -vga none'.
>>>     Output: 'qemu-system-aarch64: No machine specified, and there
>>>     is no default\nUse -machine help to list supported machines\n'.
>>>     Traceback (most recent call last):
>>>       File "<stdin>", line 1, in <module>
>>>       File "qemu.py", line 175, in launch
>>>         self._launch()
>>>       File "qemu.py", line 189, in _launch
>>>         self._post_launch()
>>>       File "qemu.py", line 154, in _post_launch
>>>         self._qmp.accept()
>>>       File "qmp/qmp.py", line 145, in accept
>>>         self.__sock, _ = self.__sock.accept()
>>>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>>>         sock, addr = self._sock.accept()
>>>     socket.timeout: timed out
>>>     >>>
>>>
>>> Signed-off-by: Amador Pahim <apahim@redhat.com>
>>> ---
>>>  scripts/qemu.py | 12 +++++++++++-
>>>  1 file changed, 11 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>>> index e9a3a96d13..43fd0b072c 100644
>>> --- a/scripts/qemu.py
>>> +++ b/scripts/qemu.py
>>> @@ -158,7 +158,10 @@ class QEMUMachine(object):
>>>              self._remove_if_exists(self._created_files.pop())
>>>
>>>      def launch(self):
>>> -        '''Launch the VM and establish a QMP connection'''
>>> +        '''
>>> +        Try to launch the VM and make sure we cleanup and expose the
>>> +        command line/output in case of exception.
>>> +        '''
>>>
>>>          if self.is_running():
>>>              raise QEMULaunchError('VM already running.')
>>> @@ -169,6 +172,7 @@ class QEMUMachine(object):
>>>                                    'before launching again.')
>>>
>>>          try:
>>> +            self._iolog = None
>>>              self._qemu_full_args = None
>>>              self._qemu_full_args = (self._wrapper + [self._binary] +
>>>                                      self._base_args() + self._args)
>>> @@ -176,9 +180,15 @@ class QEMUMachine(object):
>>>              self._pending_shutdown = True
>>>          except:
>>>              self.shutdown()
>>> +            LOG.debug('Error launching VM.%s%s',
>>> +                      ' Command: %r.' % ' '.join(self._qemu_full_args)
>>> +                      if self._qemu_full_args else '',
>>> +                      ' Output: %r.' % self._iolog
>>> +                      if self._iolog else '')
>>
>> This nested interpolation is too ugly to live :)
>
> I find it beautiful :)
> Killing it anyway.
>
>>
>> Nesting is easy to avoid:
>>
>>                LOG.debug('Error launching VM\n. ' Command: %r. Output: %r.'
>>                          % (' '.join(self._qemu_full_args)
>>                             if self._qemu_full_args else '',
>>                             self._iolog
>>                             if self._iolog else ''))
>
> In this case we will have the strings "Command: " and "Output:" even
> with no content to expose.

No command should not happen.

No output would be bad news.  Making that explicit in the logs feels
right to me.

>> Why %r and not %s?
>
> It's a matter of preference. I tend to avoid allowing messages to
> break the log line. Anyway, I'm improving this.

That's a really good point.  I'd go as far and call %s wrong now :)

Output could be arbitrarily long, though.

>> Are you sure '\n' is appropriate in the argument of LOG.debug()?
>>
>> Why cram everything into a single LOG.debug()?
>>
>>                LOG.debug('Error launching VM')
>>                LOG.debug('Command: %s' % (' '.join(self._qemu_full_args)
>>                                           if self._qemu_full_args else ''))
>>                LOG.debug('Output: %s' % self._iolog if self._iolog else ''))
>
> Sure, I'm ok with both ways.
>
>>
>>>              raise
>>>
>>>      def _launch(self):
>>> +        '''Launch the VM and establish a QMP connection.'''
>>>          self._pre_launch()
>>>          devnull = open(os.path.devnull, 'rb')
>>>          self._popen = subprocess.Popen(self._qemu_full_args,

Re: [Qemu-devel] [PATCH v6 4/7] qemu.py: improve message on negative exit code

[Amador Pahim]

On Fri, Aug 18, 2017 at 3:57 PM, Markus Armbruster <armbru@redhat.com> wrote:
> Amador Pahim <apahim@redhat.com> writes:
>
>> On Tue, Aug 15, 2017 at 10:26 AM, Markus Armbruster <armbru@redhat.com> wrote:
>>> Amador Pahim <apahim@redhat.com> writes:
>>>
>>>> The current message shows 'self._args', which contains only part of the
>>>> options used in the qemu command line.
>>>>
>>>> This patch makes the qemu full args list an instance variable and then
>>>> uses it in the negative exit code message.
>>>>
>>>> Signed-off-by: Amador Pahim <apahim@redhat.com>
>>>> ---
>>>>  scripts/qemu.py | 17 ++++++++++++-----
>>>>  1 file changed, 12 insertions(+), 5 deletions(-)
>>>>
>>>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>>>> index e3ea534ec4..9434ccc30b 100644
>>>> --- a/scripts/qemu.py
>>>> +++ b/scripts/qemu.py
>>>> @@ -48,6 +48,7 @@ class QEMUMachine(object):
>>>>          self._iolog = None
>>>>          self._socket_scm_helper = socket_scm_helper
>>>>          self._debug = debug
>>>> +        self._qemu_full_args = None
>>>>
>>>>      # This can be used to add an unused monitor instance.
>>>>      def add_monitor_telnet(self, ip, port):
>>>> @@ -140,9 +141,14 @@ class QEMUMachine(object):
>>>>          qemulog = open(self._qemu_log_path, 'wb')
>>>>          try:
>>>>              self._pre_launch()
>>>> -            args = self._wrapper + [self._binary] + self._base_args() + self._args
>>>> -            self._popen = subprocess.Popen(args, stdin=devnull, stdout=qemulog,
>>>> -                                           stderr=subprocess.STDOUT, shell=False)
>>>> +            self._qemu_full_args = None
>>>> +            self._qemu_full_args = (self._wrapper + [self._binary] +
>>>> +                                    self._base_args() + self._args)
>>>
>>> Why set self._qemu_full_args twice?
>>
>> If it's not cleaned up and an exception happens in
>> "self._qemu_full_args = (self._wrapper ...", the message logged in the
>> "except" will expose an outdated version of it.
>
> Ignorant question: why aren't we cleaning it up?

The "self._qemu_full_args = None" is the cleanup. Case the next
instruction fails, exception will have "None" instead of arguments
from a previous launch().

>
>>>> +            self._popen = subprocess.Popen(self._qemu_full_args,
>>>> +                                           stdin=devnull,
>>>> +                                           stdout=qemulog,
>>>> +                                           stderr=subprocess.STDOUT,
>>>> +                                           shell=False)
>>>>              self._post_launch()
>>>>          except:
>>>>              if self.is_running():
>>>> @@ -163,8 +169,9 @@ class QEMUMachine(object):
>>>>
>>>>              exitcode = self._popen.wait()
>>>>              if exitcode < 0:
>>>> -                LOG.error('qemu received signal %i: %s', -exitcode,
>>>> -                          ' '.join(self._args))
>>>> +                LOG.error('qemu received signal %i:%s', -exitcode,
>>>> +                          ' Command: %r.' % ' '.join(self._qemu_full_args)
>>>> +                          if self._qemu_full_args else '')
>>>
>>> The last argument is hard to read.
>>
>> Ok, I'm making it easier.
>>
>>>
>>>>              self._load_io_log()
>>>>              self._post_shutdown()
>>>
>>> The subprocess module appears to keep track of the full command with
>>> methods check_call() and check_output(): its in exception
>>> CalledProcessError right when you need it.  Sadly, it doesn't appear to
>>> be tracked with method Popen().
>>
>> Indeed.

Re: [Qemu-devel] [PATCH v6 7/7] qemu.py: include debug information on launch error

[Amador Pahim]

On Fri, Aug 18, 2017 at 4:01 PM, Markus Armbruster <armbru@redhat.com> wrote:
> Amador Pahim <apahim@redhat.com> writes:
>
>> On Tue, Aug 15, 2017 at 10:57 AM, Markus Armbruster <armbru@redhat.com> wrote:
>>> Amador Pahim <apahim@redhat.com> writes:
>>>
>>>> When launching a VM, if an exception happens and the VM is not
>>>> initiated, it is useful to see the qemu command line that was executed
>>>> and the output of that command.
>>>>
>>>> Before this patch:
>>>>
>>>>     >>> import qemu
>>>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>>>     >>> vm.launch()
>>>>     Traceback (most recent call last):
>>>>       File "<stdin>", line 1, in <module>
>>>>       File "qemu.py", line 175, in launch
>>>>         self._launch()
>>>>       File "qemu.py", line 189, in _launch
>>>>         self._post_launch()
>>>>       File "qemu.py", line 154, in _post_launch
>>>>         self._qmp.accept()
>>>>       File "qmp/qmp.py", line 145, in accept
>>>>         self.__sock, _ = self.__sock.accept()
>>>>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>>>>         sock, addr = self._sock.accept()
>>>>     socket.timeout: timed out
>>>>     >>>
>>>>
>>>> After this patch:
>>>>
>>>>     >>> import qemu
>>>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>>>     >>> vm.launch()
>>>>     DEBUG:qemu:Error launching VM. Command: 'qemu-system-aarch64
>>>>     -chardev socket,id=mon,path=/var/tmp/qemu-5298-monitor.sock
>>>>     -mon chardev=mon,mode=control -display none -vga none'.
>>>>     Output: 'qemu-system-aarch64: No machine specified, and there
>>>>     is no default\nUse -machine help to list supported machines\n'.
>>>>     Traceback (most recent call last):
>>>>       File "<stdin>", line 1, in <module>
>>>>       File "qemu.py", line 175, in launch
>>>>         self._launch()
>>>>       File "qemu.py", line 189, in _launch
>>>>         self._post_launch()
>>>>       File "qemu.py", line 154, in _post_launch
>>>>         self._qmp.accept()
>>>>       File "qmp/qmp.py", line 145, in accept
>>>>         self.__sock, _ = self.__sock.accept()
>>>>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>>>>         sock, addr = self._sock.accept()
>>>>     socket.timeout: timed out
>>>>     >>>
>>>>
>>>> Signed-off-by: Amador Pahim <apahim@redhat.com>
>>>> ---
>>>>  scripts/qemu.py | 12 +++++++++++-
>>>>  1 file changed, 11 insertions(+), 1 deletion(-)
>>>>
>>>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>>>> index e9a3a96d13..43fd0b072c 100644
>>>> --- a/scripts/qemu.py
>>>> +++ b/scripts/qemu.py
>>>> @@ -158,7 +158,10 @@ class QEMUMachine(object):
>>>>              self._remove_if_exists(self._created_files.pop())
>>>>
>>>>      def launch(self):
>>>> -        '''Launch the VM and establish a QMP connection'''
>>>> +        '''
>>>> +        Try to launch the VM and make sure we cleanup and expose the
>>>> +        command line/output in case of exception.
>>>> +        '''
>>>>
>>>>          if self.is_running():
>>>>              raise QEMULaunchError('VM already running.')
>>>> @@ -169,6 +172,7 @@ class QEMUMachine(object):
>>>>                                    'before launching again.')
>>>>
>>>>          try:
>>>> +            self._iolog = None
>>>>              self._qemu_full_args = None
>>>>              self._qemu_full_args = (self._wrapper + [self._binary] +
>>>>                                      self._base_args() + self._args)
>>>> @@ -176,9 +180,15 @@ class QEMUMachine(object):
>>>>              self._pending_shutdown = True
>>>>          except:
>>>>              self.shutdown()
>>>> +            LOG.debug('Error launching VM.%s%s',
>>>> +                      ' Command: %r.' % ' '.join(self._qemu_full_args)
>>>> +                      if self._qemu_full_args else '',
>>>> +                      ' Output: %r.' % self._iolog
>>>> +                      if self._iolog else '')
>>>
>>> This nested interpolation is too ugly to live :)
>>
>> I find it beautiful :)
>> Killing it anyway.
>>
>>>
>>> Nesting is easy to avoid:
>>>
>>>                LOG.debug('Error launching VM\n. ' Command: %r. Output: %r.'
>>>                          % (' '.join(self._qemu_full_args)
>>>                             if self._qemu_full_args else '',
>>>                             self._iolog
>>>                             if self._iolog else ''))
>>
>> In this case we will have the strings "Command: " and "Output:" even
>> with no content to expose.
>
> No command should not happen.

It can happen, if we fail before the self._qemu_full_args become ready
(i.e. if self._base_args() fails).

>
> No output would be bad news.  Making that explicit in the logs feels
> right to me.

Same here. But even more likely to happen, as one exception either
pre_launch() or launch() can trigger this message without an output.
But if that's your preference, I don't really mind having:
INFO:qemu:Error launching VM. Command: ''. Output: ''.


>
>>> Why %r and not %s?
>>
>> It's a matter of preference. I tend to avoid allowing messages to
>> break the log line. Anyway, I'm improving this.
>
> That's a really good point.  I'd go as far and call %s wrong now :)
>
> Output could be arbitrarily long, though.

Hard to say what's a sane limit. I'd prefer to log it all and let the
scripts tweak that using the logging.Formatter, if they want to.

>
>>> Are you sure '\n' is appropriate in the argument of LOG.debug()?
>>>
>>> Why cram everything into a single LOG.debug()?
>>>
>>>                LOG.debug('Error launching VM')
>>>                LOG.debug('Command: %s' % (' '.join(self._qemu_full_args)
>>>                                           if self._qemu_full_args else ''))
>>>                LOG.debug('Output: %s' % self._iolog if self._iolog else ''))
>>
>> Sure, I'm ok with both ways.
>>
>>>
>>>>              raise
>>>>
>>>>      def _launch(self):
>>>> +        '''Launch the VM and establish a QMP connection.'''
>>>>          self._pre_launch()
>>>>          devnull = open(os.path.devnull, 'rb')
>>>>          self._popen = subprocess.Popen(self._qemu_full_args,

Re: [Qemu-devel] [PATCH v6 7/7] qemu.py: include debug information on launch error

[Markus Armbruster]

Amador Pahim <apahim@redhat.com> writes:

> On Fri, Aug 18, 2017 at 4:01 PM, Markus Armbruster <armbru@redhat.com> wrote:
>> Amador Pahim <apahim@redhat.com> writes:
>>
>>> On Tue, Aug 15, 2017 at 10:57 AM, Markus Armbruster <armbru@redhat.com> wrote:
>>>> Amador Pahim <apahim@redhat.com> writes:
>>>>
>>>>> When launching a VM, if an exception happens and the VM is not
>>>>> initiated, it is useful to see the qemu command line that was executed
>>>>> and the output of that command.
>>>>>
>>>>> Before this patch:
>>>>>
>>>>>     >>> import qemu
>>>>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>>>>     >>> vm.launch()
>>>>>     Traceback (most recent call last):
>>>>>       File "<stdin>", line 1, in <module>
>>>>>       File "qemu.py", line 175, in launch
>>>>>         self._launch()
>>>>>       File "qemu.py", line 189, in _launch
>>>>>         self._post_launch()
>>>>>       File "qemu.py", line 154, in _post_launch
>>>>>         self._qmp.accept()
>>>>>       File "qmp/qmp.py", line 145, in accept
>>>>>         self.__sock, _ = self.__sock.accept()
>>>>>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>>>>>         sock, addr = self._sock.accept()
>>>>>     socket.timeout: timed out
>>>>>     >>>
>>>>>
>>>>> After this patch:
>>>>>
>>>>>     >>> import qemu
>>>>>     >>> vm = qemu.QEMUMachine('qemu-system-aarch64', debug=True)
>>>>>     >>> vm.launch()
>>>>>     DEBUG:qemu:Error launching VM. Command: 'qemu-system-aarch64
>>>>>     -chardev socket,id=mon,path=/var/tmp/qemu-5298-monitor.sock
>>>>>     -mon chardev=mon,mode=control -display none -vga none'.
>>>>>     Output: 'qemu-system-aarch64: No machine specified, and there
>>>>>     is no default\nUse -machine help to list supported machines\n'.
>>>>>     Traceback (most recent call last):
>>>>>       File "<stdin>", line 1, in <module>
>>>>>       File "qemu.py", line 175, in launch
>>>>>         self._launch()
>>>>>       File "qemu.py", line 189, in _launch
>>>>>         self._post_launch()
>>>>>       File "qemu.py", line 154, in _post_launch
>>>>>         self._qmp.accept()
>>>>>       File "qmp/qmp.py", line 145, in accept
>>>>>         self.__sock, _ = self.__sock.accept()
>>>>>       File "/usr/lib64/python2.7/socket.py", line 206, in accept
>>>>>         sock, addr = self._sock.accept()
>>>>>     socket.timeout: timed out
>>>>>     >>>
>>>>>
>>>>> Signed-off-by: Amador Pahim <apahim@redhat.com>
>>>>> ---
>>>>>  scripts/qemu.py | 12 +++++++++++-
>>>>>  1 file changed, 11 insertions(+), 1 deletion(-)
>>>>>
>>>>> diff --git a/scripts/qemu.py b/scripts/qemu.py
>>>>> index e9a3a96d13..43fd0b072c 100644
>>>>> --- a/scripts/qemu.py
>>>>> +++ b/scripts/qemu.py
>>>>> @@ -158,7 +158,10 @@ class QEMUMachine(object):
>>>>>              self._remove_if_exists(self._created_files.pop())
>>>>>
>>>>>      def launch(self):
>>>>> -        '''Launch the VM and establish a QMP connection'''
>>>>> +        '''
>>>>> +        Try to launch the VM and make sure we cleanup and expose the
>>>>> +        command line/output in case of exception.
>>>>> +        '''
>>>>>
>>>>>          if self.is_running():
>>>>>              raise QEMULaunchError('VM already running.')
>>>>> @@ -169,6 +172,7 @@ class QEMUMachine(object):
>>>>>                                    'before launching again.')
>>>>>
>>>>>          try:
>>>>> +            self._iolog = None
>>>>>              self._qemu_full_args = None
>>>>>              self._qemu_full_args = (self._wrapper + [self._binary] +
>>>>>                                      self._base_args() + self._args)
>>>>> @@ -176,9 +180,15 @@ class QEMUMachine(object):
>>>>>              self._pending_shutdown = True
>>>>>          except:
>>>>>              self.shutdown()
>>>>> +            LOG.debug('Error launching VM.%s%s',
>>>>> +                      ' Command: %r.' % ' '.join(self._qemu_full_args)
>>>>> +                      if self._qemu_full_args else '',
>>>>> +                      ' Output: %r.' % self._iolog
>>>>> +                      if self._iolog else '')
>>>>
>>>> This nested interpolation is too ugly to live :)
>>>
>>> I find it beautiful :)
>>> Killing it anyway.
>>>
>>>>
>>>> Nesting is easy to avoid:
>>>>
>>>>                LOG.debug('Error launching VM\n. ' Command: %r. Output: %r.'
>>>>                          % (' '.join(self._qemu_full_args)
>>>>                             if self._qemu_full_args else '',
>>>>                             self._iolog
>>>>                             if self._iolog else ''))
>>>
>>> In this case we will have the strings "Command: " and "Output:" even
>>> with no content to expose.
>>
>> No command should not happen.
>
> It can happen, if we fail before the self._qemu_full_args become ready
> (i.e. if self._base_args() fails).

If we fail before we even have a command line, it's not really an "Error
launching VM", it's more like "can't figure out how to launch the VM".

I suspect the root of the problem is an overly large try block.  Which
also has a catch-all except to further enhance that delicious code
smell.

I fear we have bigger fish to fry than careless error reporting.
Debating it to the n-th degree is no use; do what you think is best.

[...]

Re: [Qemu-devel] [PATCH v6 5/7] qemu.py: use os.path.null instead of /dev/null

[Philippe Mathieu-Daudé]

On 07/31/2017 05:51 AM, Amador Pahim wrote:
> For increased portability, let's use os.path.devnull.
> 
> Signed-off-by: Amador Pahim <apahim@redhat.com>

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

> ---
>   scripts/qemu.py | 4 ++--
>   1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index 9434ccc30b..d313c6d4db 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -80,7 +80,7 @@ class QEMUMachine(object):
>           fd_param = ["%s" % self._socket_scm_helper,
>                       "%d" % self._qmp.get_sock_fd(),
>                       "%s" % fd_file_path]
> -        devnull = open('/dev/null', 'rb')
> +        devnull = open(os.path.devnull, 'rb')
>           p = subprocess.Popen(fd_param, stdin=devnull, stdout=sys.stdout,
>                                stderr=sys.stderr)
>           return p.wait()
> @@ -137,7 +137,7 @@ class QEMUMachine(object):
>   
>       def launch(self):
>           '''Launch the VM and establish a QMP connection'''
> -        devnull = open('/dev/null', 'rb')
> +        devnull = open(os.path.devnull, 'rb')
>           qemulog = open(self._qemu_log_path, 'wb')
>           try:
>               self._pre_launch()
>