[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[PULL 14/24] iotests: use python logging for iotests.log()
From: |
Max Reitz |
Subject: |
[PULL 14/24] iotests: use python logging for iotests.log() |
Date: |
Tue, 5 May 2020 14:58:16 +0200 |
From: John Snow <address@hidden>
We can turn logging on/off globally instead of per-function.
Remove use_log from run_job, and use python logging to turn on
diffable output when we run through a script entry point.
iotest 245 changes output order due to buffering reasons.
An extended note on python logging:
A NullHandler is added to `qemu.iotests` to stop output from being
generated if this code is used as a library without configuring logging.
A NullHandler is only needed at the root, so a duplicate handler is not
needed for `qemu.iotests.diff_io`.
When logging is not configured, messages at the 'WARNING' levels or
above are printed with default settings. The NullHandler stops this from
occurring, which is considered good hygiene for code used as a library.
See https://docs.python.org/3/howto/logging.html#library-config
When logging is actually enabled (always at the behest of an explicit
call by a client script), a root logger is implicitly created at the
root, which allows messages to propagate upwards and be handled/emitted
from the root logger with default settings.
When we want iotest logging, we attach a handler to the
qemu.iotests.diff_io logger and disable propagation to avoid possible
double-printing.
For more information on python logging infrastructure, I highly
recommend downloading the pip package `logging_tree`, which provides
convenient visualizations of the hierarchical logging configuration
under different circumstances.
See https://pypi.org/project/logging_tree/ for more information.
Signed-off-by: John Snow <address@hidden>
Reviewed-by: Max Reitz <address@hidden>
Message-Id: <address@hidden>
Reviewed-by: Kevin Wolf <address@hidden>
Signed-off-by: Max Reitz <address@hidden>
---
tests/qemu-iotests/030 | 4 +--
tests/qemu-iotests/155 | 2 +-
tests/qemu-iotests/245 | 1 +
tests/qemu-iotests/245.out | 10 +++----
tests/qemu-iotests/iotests.py | 53 ++++++++++++++++++++---------------
5 files changed, 39 insertions(+), 31 deletions(-)
diff --git a/tests/qemu-iotests/030 b/tests/qemu-iotests/030
index aa911d266a..104e3cee1b 100755
--- a/tests/qemu-iotests/030
+++ b/tests/qemu-iotests/030
@@ -411,8 +411,8 @@ class TestParallelOps(iotests.QMPTestCase):
result = self.vm.qmp('block-job-set-speed', device='drive0', speed=0)
self.assert_qmp(result, 'return', {})
- self.vm.run_job(job='drive0', auto_dismiss=True, use_log=False)
- self.vm.run_job(job='node4', auto_dismiss=True, use_log=False)
+ self.vm.run_job(job='drive0', auto_dismiss=True)
+ self.vm.run_job(job='node4', auto_dismiss=True)
self.assert_no_active_block_jobs()
# Test a block-stream and a block-commit job in parallel
diff --git a/tests/qemu-iotests/155 b/tests/qemu-iotests/155
index 571bce9de4..cb371d4649 100755
--- a/tests/qemu-iotests/155
+++ b/tests/qemu-iotests/155
@@ -188,7 +188,7 @@ class MirrorBaseClass(BaseClass):
self.assert_qmp(result, 'return', {})
- self.vm.run_job('mirror-job', use_log=False, auto_finalize=False,
+ self.vm.run_job('mirror-job', auto_finalize=False,
pre_finalize=self.openBacking, auto_dismiss=True)
def testFull(self):
diff --git a/tests/qemu-iotests/245 b/tests/qemu-iotests/245
index 1001275a44..4f5f0bb901 100755
--- a/tests/qemu-iotests/245
+++ b/tests/qemu-iotests/245
@@ -1027,5 +1027,6 @@ class TestBlockdevReopen(iotests.QMPTestCase):
self.run_test_iothreads(None, 'iothread0')
if __name__ == '__main__':
+ iotests.activate_logging()
iotests.main(supported_fmts=["qcow2"],
supported_protocols=["file"])
diff --git a/tests/qemu-iotests/245.out b/tests/qemu-iotests/245.out
index 682b93394d..4b33dcaf5c 100644
--- a/tests/qemu-iotests/245.out
+++ b/tests/qemu-iotests/245.out
@@ -1,8 +1,3 @@
-.....................
-----------------------------------------------------------------------
-Ran 21 tests
-
-OK
{"execute": "job-finalize", "arguments": {"id": "commit0"}}
{"return": {}}
{"data": {"id": "commit0", "type": "commit"}, "event": "BLOCK_JOB_PENDING",
"timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
@@ -15,3 +10,8 @@ OK
{"return": {}}
{"data": {"id": "stream0", "type": "stream"}, "event": "BLOCK_JOB_PENDING",
"timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"device": "stream0", "len": 3145728, "offset": 3145728, "speed": 0,
"type": "stream"}, "event": "BLOCK_JOB_COMPLETED", "timestamp":
{"microseconds": "USECS", "seconds": "SECS"}}
+.....................
+----------------------------------------------------------------------
+Ran 21 tests
+
+OK
diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
index 35d8cae997..6c0e781af7 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -42,6 +42,14 @@ assert sys.version_info >= (3, 6)
QMPResponse = Dict[str, Any]
+# Use this logger for logging messages directly from the iotests module
+logger = logging.getLogger('qemu.iotests')
+logger.addHandler(logging.NullHandler())
+
+# Use this logger for messages that ought to be used for diff output.
+test_logger = logging.getLogger('qemu.iotests.diff_io')
+
+
faulthandler.enable()
# This will not work if arguments contain spaces but is necessary if we
@@ -385,9 +393,9 @@ def log(msg: Msg,
if isinstance(msg, (dict, list)):
# Don't sort if it's already sorted
do_sort = not isinstance(msg, OrderedDict)
- print(json.dumps(msg, sort_keys=do_sort, indent=indent))
+ test_logger.info(json.dumps(msg, sort_keys=do_sort, indent=indent))
else:
- print(msg)
+ test_logger.info(msg)
class Timeout:
def __init__(self, seconds, errmsg="Timeout"):
@@ -609,7 +617,7 @@ class VM(qtest.QEMUQtestMachine):
# Returns None on success, and an error string on failure
def run_job(self, job, auto_finalize=True, auto_dismiss=False,
- pre_finalize=None, cancel=False, use_log=True, wait=60.0):
+ pre_finalize=None, cancel=False, wait=60.0):
"""
run_job moves a job from creation through to dismissal.
@@ -622,7 +630,6 @@ class VM(qtest.QEMUQtestMachine):
invoked prior to issuing job-finalize, if any.
:param cancel: Bool. When true, cancels the job after the pre_finalize
callback.
- :param use_log: Bool. When false, does not log QMP messages.
:param wait: Float. Timeout value specifying how long to wait for any
event, in seconds. Defaults to 60.0.
"""
@@ -640,8 +647,7 @@ class VM(qtest.QEMUQtestMachine):
while True:
ev = filter_qmp_event(self.events_wait(events, timeout=wait))
if ev['event'] != 'JOB_STATUS_CHANGE':
- if use_log:
- log(ev)
+ log(ev)
continue
status = ev['data']['status']
if status == 'aborting':
@@ -649,29 +655,18 @@ class VM(qtest.QEMUQtestMachine):
for j in result['return']:
if j['id'] == job:
error = j['error']
- if use_log:
- log('Job failed: %s' % (j['error']))
+ log('Job failed: %s' % (j['error']))
elif status == 'ready':
- if use_log:
- self.qmp_log('job-complete', id=job)
- else:
- self.qmp('job-complete', id=job)
+ self.qmp_log('job-complete', id=job)
elif status == 'pending' and not auto_finalize:
if pre_finalize:
pre_finalize()
- if cancel and use_log:
+ if cancel:
self.qmp_log('job-cancel', id=job)
- elif cancel:
- self.qmp('job-cancel', id=job)
- elif use_log:
- self.qmp_log('job-finalize', id=job)
else:
- self.qmp('job-finalize', id=job)
+ self.qmp_log('job-finalize', id=job)
elif status == 'concluded' and not auto_dismiss:
- if use_log:
- self.qmp_log('job-dismiss', id=job)
- else:
- self.qmp('job-dismiss', id=job)
+ self.qmp_log('job-dismiss', id=job)
elif status == 'null':
return error
@@ -991,7 +986,7 @@ def notrun(reason):
seq = os.path.basename(sys.argv[0])
open('%s/%s.notrun' % (output_dir, seq), 'w').write(reason + '\n')
- print('%s not run: %s' % (seq, reason))
+ logger.warning("%s not run: %s", seq, reason)
sys.exit(0)
def case_notrun(reason):
@@ -1183,6 +1178,7 @@ def execute_setup_common(supported_fmts: Sequence[str] =
(),
if debug:
sys.argv.remove('-d')
logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
+ logger.debug("iotests debugging messages active")
return debug
@@ -1195,14 +1191,25 @@ def execute_test(*args, test_function=None, **kwargs):
else:
test_function()
+def activate_logging():
+ """Activate iotests.log() output to stdout for script-style tests."""
+ handler = logging.StreamHandler(stream=sys.stdout)
+ formatter = logging.Formatter('%(message)s')
+ handler.setFormatter(formatter)
+ test_logger.addHandler(handler)
+ test_logger.setLevel(logging.INFO)
+ test_logger.propagate = False
+
# This is called from script-style iotests without a single point of entry
def script_initialize(*args, **kwargs):
"""Initialize script-style tests without running any tests."""
+ activate_logging()
execute_setup_common(*args, **kwargs)
# This is called from script-style iotests with a single point of entry
def script_main(test_function, *args, **kwargs):
"""Run script-style tests outside of the unittest framework"""
+ activate_logging()
execute_test(*args, test_function=test_function, **kwargs)
# This is called from unittest style iotests
--
2.26.2
- [PULL 05/24] iotests: add pylintrc file, (continued)
- [PULL 05/24] iotests: add pylintrc file, Max Reitz, 2020/05/05
- [PULL 07/24] iotests: drop pre-Python 3.4 compatibility code, Max Reitz, 2020/05/05
- [PULL 01/24] iotests: do a light delinting, Max Reitz, 2020/05/05
- [PULL 08/24] iotests: touch up log function signature, Max Reitz, 2020/05/05
- [PULL 10/24] iotests: add hmp helper with logging, Max Reitz, 2020/05/05
- [PULL 11/24] iotests: add script_initialize, Max Reitz, 2020/05/05
- [PULL 12/24] iotest 258: use script_main, Max Reitz, 2020/05/05
- [PULL 09/24] iotests: limit line length to 79 chars, Max Reitz, 2020/05/05
- [PULL 13/24] iotests: Mark verify functions as private, Max Reitz, 2020/05/05
- [PULL 17/24] qcow2: Tweak comment about bitmaps vs. resize, Max Reitz, 2020/05/05
- [PULL 14/24] iotests: use python logging for iotests.log(),
Max Reitz <=
- [PULL 18/24] block: Comment cleanups, Max Reitz, 2020/05/05
- [PULL 20/24] block/block-copy: rename in-flight requests to tasks, Max Reitz, 2020/05/05
- [PULL 21/24] block/block-copy: alloc task on each iteration, Max Reitz, 2020/05/05
- [PULL 19/24] Fix iotest 153, Max Reitz, 2020/05/05
- [PULL 15/24] block: Add blk_new_with_bs() helper, Max Reitz, 2020/05/05
- [PULL 22/24] block/block-copy: add state pointer to BlockCopyTask, Max Reitz, 2020/05/05
- [PULL 23/24] block/block-copy: refactor task creation, Max Reitz, 2020/05/05
- [PULL 16/24] qcow2: Allow resize of images with internal snapshots, Max Reitz, 2020/05/05
- [PULL 24/24] block/block-copy: use aio-task-pool API, Max Reitz, 2020/05/05