qemu.py: Call logging.basicConfig() automatically

PATCH In review Eduardo Habkost 4 participants 6 messages Sep 21, 2017 – Sep 24, 2017

Share & tools

Eduardo Habkost

author

2017-09-21 16:22 UTC #0 lore raw

PATCH 1/1 qemu.py: Call logging.basicConfig() automatically

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 <[email protected]>

Fixes 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1

Signed-off-by Eduardo Habkost <[email protected]>

---
 scripts/qemu.py | 3 +++
 1 file changed, 3 insertions(+)

scripts/qemu.py +3 -0

index 5e02dd8e78..73d6031e02 100644
@@ -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

Signature · 1 line

2.13.5

Cleber Rosa

Reviewed-by on v1 1/1

2017-09-21 16:34 UTC #1 lore raw

Quoted 23 lines · 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 <[email protected]>
Fixes 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
Signed-off-by Eduardo Habkost <[email protected]>
---
 scripts/qemu.py | 3 +++
 1 file changed, 3 insertions(+)
scripts/qemu.py +0 -0
index 5e02dd8e78..73d6031e02 100644

scripts/qemu.py class QEMUMachine(object): · line 97

Quoted 9 lines

scripts/qemu.py +3 -0

@@ -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 <[email protected]>

Lukáš Doktor

Acked-by on v1 1/1

2017-09-22 08:37 UTC #2 lore raw

In reply to Eduardo Habkost

Dne 21.9.2017 v 18:22 Eduardo Habkost napsal(a):

Quoted 23 lines

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 <[email protected]>
Fixes 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
Signed-off-by Eduardo Habkost <[email protected]>
---
 scripts/qemu.py | 3 +++
 1 file changed, 3 insertions(+)
scripts/qemu.py +0 -0
index 5e02dd8e78..73d6031e02 100644

scripts/qemu.py class QEMUMachine(object): · line 97

Quoted 9 lines

scripts/qemu.py +3 -0

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

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 <[email protected]>

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

Kevin Wolf

2017-09-22 09:40 UTC #3 lore raw

Am 22.09.2017 um 10:37 hat Lukáš Doktor geschrieben:

Quoted 5 lines

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

Lukáš Doktor

2017-09-24 11:17 UTC #4 lore raw

Dne 22.9.2017 v 11:40 Kevin Wolf napsal(a):

Quoted 7 lines

Am 22.09.2017 um 10:37 hat Lukáš Doktor geschrieben:
Quoted 5 lines
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.

Quoted 9 lines

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

Quoted 2 lines

Kevin

Eduardo Habkost

author

2017-09-22 12:47 UTC #5 lore raw

In reply to Lukáš Doktor

Quoted 54 lines · Lukáš Doktor

Dne 21.9.2017 v 18:22 Eduardo Habkost napsal(a):
Quoted 23 lines
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 <[email protected]>
Fixes 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
Signed-off-by Eduardo Habkost <[email protected]>
---
 scripts/qemu.py | 3 +++
 1 file changed, 3 insertions(+)
scripts/qemu.py +0 -0
index 5e02dd8e78..73d6031e02 100644
scripts/qemu.py class QEMUMachine(object): · line 97
Quoted 9 lines
scripts/qemu.py +3 -0
@@ -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...

Quoted 10 lines

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.

Quoted 9 lines

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 <[email protected]>

Thanks!

Quoted 9 lines

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 · 1 line

Eduardo