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

[Lukáš Doktor]

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
> 




signature.asc
Description: OpenPGP digital signature

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 
> > Fixes: 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
> > Signed-off-by: Eduardo Habkost 
> > ---
> >  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 

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

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

[Kevin Wolf]

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


signature.asc
Description: PGP signature

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

[Lukáš Doktor]

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 
> Fixes: 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
> Signed-off-by: Eduardo Habkost 
> ---
>  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 

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áš



signature.asc
Description: OpenPGP digital signature

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 
> Fixes: 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
> Signed-off-by: Eduardo Habkost 
> ---
>  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