| Message ID | 20170921162234.847-1-ehabkost@redhat.com |
|---|---|
| State | New |
| Headers | show |
| Series | qemu.py: Call logging.basicConfig() automatically | expand |
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>
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áš
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
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áš >
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 >
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
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(+)