qemu.py: Call logging.basicConfig() automatically
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.
--- scripts/qemu.py | 3 +++ 1 file changed, 3 insertions(+)
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
Signature · 1 line
2.13.5
Quoted 23 lines · Eduardo Habkost
Not all scripts using
qemu.pyconfigure 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.pyto configure logging manually, callbasicConfig()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 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1Signed-off-by Eduardo Habkost <[email protected]>--- scripts/qemu.py | 3 +++ 1 file changed, 3 insertions(+)scripts/qemu.py +0
-0
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."
Dne 21.9.2017 v 18:22 Eduardo Habkost napsal(a):
Quoted 23 lines
Not all scripts using
qemu.pyconfigure 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.pyto configure logging manually, callbasicConfig()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 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1Signed-off-by Eduardo Habkost <[email protected]>--- scripts/qemu.py | 3 +++ 1 file changed, 3 insertions(+)scripts/qemu.py +0
-0
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...
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**:
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:
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
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
Quoted 54 lines · Lukáš Doktor
Dne 21.9.2017 v 18:22 Eduardo Habkost napsal(a):
Quoted 23 lines
Not all scripts using
qemu.pyconfigure 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.pyto configure logging manually, callbasicConfig()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 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1Signed-off-by Eduardo Habkost <[email protected]>--- scripts/qemu.py | 3 +++ 1 file changed, 3 insertions(+)scripts/qemu.py +0
-0scripts/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 selfHello 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 qemuwould 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