diff mbox

[v6,3/7] qemu.py: use python logging system

Message ID 20170731085110.1050-4-apahim@redhat.com
State New
Headers show

Commit Message

Amador Pahim July 31, 2017, 8:51 a.m. UTC
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(-)

Comments

Eduardo Habkost July 31, 2017, 2:50 p.m. UTC | #1
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
>
Amador Pahim July 31, 2017, 3:05 p.m. UTC | #2
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
Markus Armbruster Aug. 15, 2017, 8:10 a.m. UTC | #3
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.
Eduardo Habkost Aug. 15, 2017, 7:58 p.m. UTC | #4
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.
Markus Armbruster Aug. 16, 2017, 6:17 a.m. UTC | #5
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.
Amador Pahim Aug. 18, 2017, 12:24 p.m. UTC | #6
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.
diff mbox

Patch

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()