* [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically
@ 2017-09-21 16:22 Eduardo Habkost
2017-09-21 16:34 ` Cleber Rosa
2017-09-22 8:37 ` Lukáš Doktor
0 siblings, 2 replies; 6+ messages in thread
From: Eduardo Habkost @ 2017-09-21 16:22 UTC (permalink / raw)
To: qemu-devel
Cc: Kevin Wolf, Cleber Rosa, Amador Pahim, Fam Zheng, ldoktor,
stefanha, armbru, mreitz
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
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically
2017-09-21 16:22 [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically Eduardo Habkost
@ 2017-09-21 16:34 ` Cleber Rosa
2017-09-22 8:37 ` Lukáš Doktor
1 sibling, 0 replies; 6+ messages in thread
From: Cleber Rosa @ 2017-09-21 16:34 UTC (permalink / raw)
To: Eduardo Habkost, qemu-devel
Cc: Kevin Wolf, Amador Pahim, Fam Zheng, ldoktor, stefanha, armbru,
mreitz
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>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically
2017-09-21 16:22 [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically Eduardo Habkost
2017-09-21 16:34 ` Cleber Rosa
@ 2017-09-22 8:37 ` Lukáš Doktor
2017-09-22 9:40 ` Kevin Wolf
2017-09-22 12:47 ` Eduardo Habkost
1 sibling, 2 replies; 6+ messages in thread
From: Lukáš Doktor @ 2017-09-22 8:37 UTC (permalink / raw)
To: Eduardo Habkost, qemu-devel
Cc: Kevin Wolf, Cleber Rosa, Amador Pahim, Fam Zheng, stefanha,
armbru, mreitz
[-- 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 --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically
2017-09-22 8:37 ` Lukáš Doktor
@ 2017-09-22 9:40 ` Kevin Wolf
2017-09-24 11:17 ` Lukáš Doktor
2017-09-22 12:47 ` Eduardo Habkost
1 sibling, 1 reply; 6+ messages in thread
From: Kevin Wolf @ 2017-09-22 9:40 UTC (permalink / raw)
To: Lukáš Doktor
Cc: Eduardo Habkost, qemu-devel, Cleber Rosa, Amador Pahim, Fam Zheng,
stefanha, armbru, mreitz
[-- 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 --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically
2017-09-22 8:37 ` Lukáš Doktor
2017-09-22 9:40 ` Kevin Wolf
@ 2017-09-22 12:47 ` Eduardo Habkost
1 sibling, 0 replies; 6+ messages in thread
From: Eduardo Habkost @ 2017-09-22 12:47 UTC (permalink / raw)
To: Lukáš Doktor
Cc: qemu-devel, Kevin Wolf, Cleber Rosa, Amador Pahim, Fam Zheng,
stefanha, armbru, mreitz
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
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically
2017-09-22 9:40 ` Kevin Wolf
@ 2017-09-24 11:17 ` Lukáš Doktor
0 siblings, 0 replies; 6+ messages in thread
From: Lukáš Doktor @ 2017-09-24 11:17 UTC (permalink / raw)
To: Kevin Wolf
Cc: Eduardo Habkost, qemu-devel, Cleber Rosa, Amador Pahim, Fam Zheng,
stefanha, armbru, mreitz
[-- 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 --]
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2017-09-24 11:17 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-09-21 16:22 [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically Eduardo Habkost
2017-09-21 16:34 ` Cleber Rosa
2017-09-22 8:37 ` Lukáš Doktor
2017-09-22 9:40 ` Kevin Wolf
2017-09-24 11:17 ` Lukáš Doktor
2017-09-22 12:47 ` Eduardo Habkost
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).