[Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically

[Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically

[Eduardo Habkost]

Not all scripts using qemu.py configure the Python logging
module, and end up generating a "No handlers could be found for
logger" message instead of actual log messages.

To avoid requiring every script using qemu.py to configure
logging manually, call basicConfig() when creating a QEMUMachine
object.  This won't affect scripts that already set up logging,
but will ensure that scripts that don't configure logging keep
working.

Reported-by: Kevin Wolf <kwolf@redhat.com>
Fixes: 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
Signed-off-by: Eduardo Habkost <ehabkost@redhat.com>
---
 scripts/qemu.py | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/scripts/qemu.py b/scripts/qemu.py
index 5e02dd8e78..73d6031e02 100644
--- a/scripts/qemu.py
+++ b/scripts/qemu.py
@@ -89,6 +89,9 @@ class QEMUMachine(object):
         self._qmp = None
         self._qemu_full_args = None
 
+        # just in case logging wasn't configured by the main script:
+        logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
+
     def __enter__(self):
         return self
 
-- 
2.13.5

Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically

[Cleber Rosa]

On 09/21/2017 12:22 PM, Eduardo Habkost wrote:
> Not all scripts using qemu.py configure the Python logging
> module, and end up generating a "No handlers could be found for
> logger" message instead of actual log messages.
> 
> To avoid requiring every script using qemu.py to configure
> logging manually, call basicConfig() when creating a QEMUMachine
> object.  This won't affect scripts that already set up logging,
> but will ensure that scripts that don't configure logging keep
> working.
> 
> Reported-by: Kevin Wolf <kwolf@redhat.com>
> Fixes: 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
> Signed-off-by: Eduardo Habkost <ehabkost@redhat.com>
> ---
>  scripts/qemu.py | 3 +++
>  1 file changed, 3 insertions(+)
> 
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index 5e02dd8e78..73d6031e02 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -89,6 +89,9 @@ class QEMUMachine(object):
>          self._qmp = None
>          self._qemu_full_args = None
>  
> +        # just in case logging wasn't configured by the main script:
> +        logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
> +
>      def __enter__(self):
>          return self
>  
> 

Your description is accurate, and backed by:

https://docs.python.org/3/library/logging.html#logging.basicConfig

Quoting the relevant section: "This function does nothing if the root
logger already has handlers configured for it."

Reviewed-by: Cleber Rosa <crosa@redhat.com>

Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically

[Lukáš Doktor]

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

Dne 21.9.2017 v 18:22 Eduardo Habkost napsal(a):
> Not all scripts using qemu.py configure the Python logging
> module, and end up generating a "No handlers could be found for
> logger" message instead of actual log messages.
> 
> To avoid requiring every script using qemu.py to configure
> logging manually, call basicConfig() when creating a QEMUMachine
> object.  This won't affect scripts that already set up logging,
> but will ensure that scripts that don't configure logging keep
> working.
> 
> Reported-by: Kevin Wolf <kwolf@redhat.com>
> Fixes: 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
> Signed-off-by: Eduardo Habkost <ehabkost@redhat.com>
> ---
>  scripts/qemu.py | 3 +++
>  1 file changed, 3 insertions(+)
> 
> diff --git a/scripts/qemu.py b/scripts/qemu.py
> index 5e02dd8e78..73d6031e02 100644
> --- a/scripts/qemu.py
> +++ b/scripts/qemu.py
> @@ -89,6 +89,9 @@ class QEMUMachine(object):
>          self._qmp = None
>          self._qemu_full_args = None
>  
> +        # just in case logging wasn't configured by the main script:
> +        logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
> +
>      def __enter__(self):
>          return self
>  
> 

Hello Eduardo,

what troubles me about this approach is it enables debug based on first instance arguments, while other instances might use a different value. Ideally we should create `"%s.%s" % (__name__, id(self))` logger per each instance and only set this log level there. The same would have to happen for QMP and other modules, which should either use the configured instance's logger, or create own logger as a child of that logger and optionally tweaked the levels there (if necessary), so the result would be:

QEMUMachine(debug=True)
QEMUMachine(debug=False)

qemu.139855463298312: DEBUG: Starting instance 139855463298312
qemu.139855463298312.qmp: DEBUG: Initializing connection to qmp
qemu.139855463298312: INFO: Started qemu cmd...
qemu.139855463216512: INFO: Started qemu cmd...

while with your patch you get:

qemu.139855463298312: DEBUG: Starting instance 139855463298312
qemu.139855463298312.qmp: DEBUG: Initializing connection to qmp
qemu.139855463298312: INFO: Started qemu cmd...
qemu.139855463216512: DEBUG: Starting instance 139855463298312
qemu.139855463216512.qmp: DEBUG: Initializing connection to qmp
qemu.139855463216512: INFO: Started qemu cmd...


But mine approach would break other scripts that call logging.baseConfig (eg. qemu/device-crash-test), because they rely on root logger's log-level (because `import qemu` would have issued logging.baseConfig). I can't come-up with a better alternative and this indeed fixes the issues with scripts using qemu without initializing loggers so considering this as a **hotfix**:

Acked-by: Lukáš Doktor <ldoktor@redhat.com>

But we should focus on fixing all the entry points (either initialize from all of them, or force-create the root logger based on the entry-point requirements). Kevin, could you please share the exact reproducer? I used a custom file importing QEMUMachine() with a some added LOG calls.

Lukáš


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 502 bytes --]

Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically

[Kevin Wolf]

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

Am 22.09.2017 um 10:37 hat Lukáš Doktor geschrieben:
> But we should focus on fixing all the entry points (either initialize
> from all of them, or force-create the root logger based on the
> entry-point requirements). Kevin, could you please share the exact
> reproducer? I used a custom file importing QEMUMachine() with a some
> added LOG calls.

I was running qemu-iotests 030 on a development branch that had a bug
that made qemu segfault. This should result in a logged 'qemu received
signal 6' message, but only prints the logging error now. The same kind
of problem affects all Python-based tests in the tree, git grep didn't
find any that initialise the logger manually.

In order to reproduce, you can fake such a crash by inserting an HMP
command like 'qemu-io ide0-hd0 abort' somewhere in a Python-based test.

Kevin

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

Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically

[Lukáš Doktor]

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

Dne 22.9.2017 v 11:40 Kevin Wolf napsal(a):
> Am 22.09.2017 um 10:37 hat Lukáš Doktor geschrieben:
>> But we should focus on fixing all the entry points (either initialize
>> from all of them, or force-create the root logger based on the
>> entry-point requirements). Kevin, could you please share the exact
>> reproducer? I used a custom file importing QEMUMachine() with a some
>> added LOG calls.
> 
> I was running qemu-iotests 030 on a development branch that had a bug
> that made qemu segfault. This should result in a logged 'qemu received
> signal 6' message, but only prints the logging error now. The same kind
> of problem affects all Python-based tests in the tree, git grep didn't
> find any that initialise the logger manually.
> 
> In order to reproduce, you can fake such a crash by inserting an HMP
> command like 'qemu-io ide0-hd0 abort' somewhere in a Python-based test.
> 
OK, that's basically what I did. As a proper fix would require all tests to initialize logging (even if as an extra call to `iotests.initialize_logging` or `qemu.initialize_logging` I think Eduardo's patch actually fits the usage within qemu/scripts. Sorry for over-thinking this.

Lukáš

> Kevin
> 



[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 502 bytes --]

Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically

[Eduardo Habkost]

On Fri, Sep 22, 2017 at 10:37:44AM +0200, Lukáš Doktor wrote:
> Dne 21.9.2017 v 18:22 Eduardo Habkost napsal(a):
> > Not all scripts using qemu.py configure the Python logging
> > module, and end up generating a "No handlers could be found for
> > logger" message instead of actual log messages.
> > 
> > To avoid requiring every script using qemu.py to configure
> > logging manually, call basicConfig() when creating a QEMUMachine
> > object.  This won't affect scripts that already set up logging,
> > but will ensure that scripts that don't configure logging keep
> > working.
> > 
> > Reported-by: Kevin Wolf <kwolf@redhat.com>
> > Fixes: 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
> > Signed-off-by: Eduardo Habkost <ehabkost@redhat.com>
> > ---
> >  scripts/qemu.py | 3 +++
> >  1 file changed, 3 insertions(+)
> > 
> > diff --git a/scripts/qemu.py b/scripts/qemu.py
> > index 5e02dd8e78..73d6031e02 100644
> > --- a/scripts/qemu.py
> > +++ b/scripts/qemu.py
> > @@ -89,6 +89,9 @@ class QEMUMachine(object):
> >          self._qmp = None
> >          self._qemu_full_args = None
> >  
> > +        # just in case logging wasn't configured by the main script:
> > +        logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
> > +
> >      def __enter__(self):
> >          return self
> >  
> > 
> 
> Hello Eduardo,
> 
> what troubles me about this approach is it enables debug based
> on first instance arguments, while other instances might use a
> different value. Ideally we should create `"%s.%s" % (__name__,
> id(self))` logger per each instance and only set this log level
> there. The same would have to happen for QMP and other modules,
> which should either use the configured instance's logger, or
> create own logger as a child of that logger and optionally
> tweaked the levels there (if necessary), so the result would
> be:
> 
> QEMUMachine(debug=True)
> QEMUMachine(debug=False)
> 
> qemu.139855463298312: DEBUG: Starting instance 139855463298312
> qemu.139855463298312.qmp: DEBUG: Initializing connection to qmp
> qemu.139855463298312: INFO: Started qemu cmd...
> qemu.139855463216512: INFO: Started qemu cmd...
> 
> while with your patch you get:
> 
> qemu.139855463298312: DEBUG: Starting instance 139855463298312
> qemu.139855463298312.qmp: DEBUG: Initializing connection to qmp
> qemu.139855463298312: INFO: Started qemu cmd...
> qemu.139855463216512: DEBUG: Starting instance 139855463298312
> qemu.139855463216512.qmp: DEBUG: Initializing connection to qmp
> qemu.139855463216512: INFO: Started qemu cmd...
> 
> 

IMO, the solution for that is to obsolete the 'debug' parameter
and use the Python logging configuration to control QEMUMachine
logging.  Most (or all?) scripts have a global verbosity setting,
anyway.

> But mine approach would break other scripts that call
> logging.baseConfig (eg. qemu/device-crash-test), because they
> rely on root logger's log-level (because `import qemu` would
> have issued logging.baseConfig). I can't come-up with a better
> alternative and this indeed fixes the issues with scripts using
> qemu without initializing loggers so considering this as a
> **hotfix**:
> 
> Acked-by: Lukáš Doktor <ldoktor@redhat.com>

Thanks!

> 
> But we should focus on fixing all the entry points (either
> initialize from all of them, or force-create the root logger
> based on the entry-point requirements). Kevin, could you please
> share the exact reproducer? I used a custom file importing
> QEMUMachine() with a some added LOG calls.
> 
> Lukáš
> 

-- 
Eduardo