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.
---
tests/qemu-iotests/030 | 4 +--
tests/qemu-iotests/245 | 1 +
tests/qemu-iotests/245.out | 24 +++++++++---------
tests/qemu-iotests/iotests.py | 47 +++++++++++++++++++++--------------
4 files changed, 43 insertions(+), 33 deletions(-)
diff --git a/tests/qemu-iotests/030 b/tests/qemu-iotests/030
index 1b69f318c6..a382cb430b 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/245 b/tests/qemu-iotests/245
index bc1ceb9792..3bc29acb33 100644
--- a/tests/qemu-iotests/245
+++ b/tests/qemu-iotests/245
@@ -1000,4 +1000,5 @@ class TestBlockdevReopen(iotests.QMPTestCase):
self.reopen(opts, {'backing': 'hd2'})
if __name__ == '__main__':
+ iotests.activate_logging()
iotests.main(supported_fmts=["qcow2"])
diff --git a/tests/qemu-iotests/245.out b/tests/qemu-iotests/245.out
index a19de5214d..15c3630e92 100644
--- a/tests/qemu-iotests/245.out
+++ b/tests/qemu-iotests/245.out
@@ -1,17 +1,17 @@
+{"execute": "job-finalize", "arguments": {"id": "commit0"}}
+{"return": {}}
+{"data": {"id": "commit0", "type": "commit"}, "event": "BLOCK_JOB_PENDING", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
+{"data": {"device": "commit0", "len": 3145728, "offset": 3145728, "speed": 0, "type": "commit"}, "event": "BLOCK_JOB_COMPLETED", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
+{"execute": "job-finalize", "arguments": {"id": "stream0"}}
+{"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"}}
+{"execute": "job-finalize", "arguments": {"id": "stream0"}}
+{"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 18 tests
OK
-{"execute": "job-finalize", "arguments": {"id": "commit0"}}
-{"return": {}}
-{"data": {"id": "commit0", "type": "commit"}, "event": "BLOCK_JOB_PENDING", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
-{"data": {"device": "commit0", "len": 3145728, "offset": 3145728, "speed": 0, "type": "commit"}, "event": "BLOCK_JOB_COMPLETED", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
-{"execute": "job-finalize", "arguments": {"id": "stream0"}}
-{"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"}}
-{"execute": "job-finalize", "arguments": {"id": "stream0"}}
-{"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"}}
diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
index 661d7f93bf..b97cc2fab2 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -35,6 +35,13 @@ from collections import OrderedDict
sys.path.append(os.path.join(os.path.dirname(__file__), '..', '..', 'python'))
from qemu import qtest
+# Use this logger for logging messages directly from the iotests module
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
+
+# Use this logger for messages that ought to be used for diff output.
+test_logger = logging.getLogger('.'.join((__name__, 'iotest')))
+test_logger.addHandler(logging.NullHandler())
# This will not work if arguments contain spaces but is necessary if we
# want to support the override options that ./check supports.
@@ -343,10 +350,10 @@ def log(msg, filters=[], indent=None):
separators = (', ', ': ') if indent is None else (',', ': ')
# Don't sort if it's already sorted
do_sort = not isinstance(msg, OrderedDict)
- print(json.dumps(msg, sort_keys=do_sort,
- indent=indent, separators=separators))
+ test_logger.info(json.dumps(msg, sort_keys=do_sort,
+ indent=indent, separators=separators))
else:
- print(msg)
+ test_logger.info(msg)
class Timeout:
def __init__(self, seconds, errmsg = "Timeout"):
@@ -559,7 +566,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.
@@ -572,7 +579,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.
"""
@@ -590,8 +596,7 @@ class VM(qtest.QEMUQtestMachine):
while True:
ev = filter_qmp_event(self.events_wait(events))
if ev['event'] != 'JOB_STATUS_CHANGE':
- if use_log:
- log(ev)
+ log(ev)
continue
status = ev['data']['status']
if status == 'aborting':
@@ -599,24 +604,16 @@ 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 == '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:
+ else:
self.qmp_log('job-finalize', id=job)
- else:
- self.qmp('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
@@ -949,6 +946,7 @@ def execute_setup_common(supported_fmts=[],
if debug:
sys.argv.remove('-d')
logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
+ logger.debug("iotests debugging messages active")
return debug
@@ -961,14 +959,25 @@ def execute_test(test_function=None, *args, **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(test_function, *args, **kwargs)
# This is called from unittest style iotests
--
2.21.0
On 8/21/19 1:52 AM, John Snow wrote:
> 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.
> ---
> tests/qemu-iotests/030 | 4 +--
> tests/qemu-iotests/245 | 1 +
> tests/qemu-iotests/245.out | 24 +++++++++---------
> tests/qemu-iotests/iotests.py | 47 +++++++++++++++++++++--------------
> 4 files changed, 43 insertions(+), 33 deletions(-)
>
> diff --git a/tests/qemu-iotests/030 b/tests/qemu-iotests/030
> index 1b69f318c6..a382cb430b 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/245 b/tests/qemu-iotests/245
> index bc1ceb9792..3bc29acb33 100644
> --- a/tests/qemu-iotests/245
> +++ b/tests/qemu-iotests/245
> @@ -1000,4 +1000,5 @@ class TestBlockdevReopen(iotests.QMPTestCase):
> self.reopen(opts, {'backing': 'hd2'})
>
> if __name__ == '__main__':
> + iotests.activate_logging()
> iotests.main(supported_fmts=["qcow2"])
Why not use:
iotests.script_main(iotests.main, supported_fmts=['qcow2')
> diff --git a/tests/qemu-iotests/245.out b/tests/qemu-iotests/245.out
> index a19de5214d..15c3630e92 100644
> --- a/tests/qemu-iotests/245.out
> +++ b/tests/qemu-iotests/245.out
> @@ -1,17 +1,17 @@
> +{"execute": "job-finalize", "arguments": {"id": "commit0"}}
> +{"return": {}}
> +{"data": {"id": "commit0", "type": "commit"}, "event": "BLOCK_JOB_PENDING", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
> +{"data": {"device": "commit0", "len": 3145728, "offset": 3145728, "speed": 0, "type": "commit"}, "event": "BLOCK_JOB_COMPLETED", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
> +{"execute": "job-finalize", "arguments": {"id": "stream0"}}
> +{"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"}}
> +{"execute": "job-finalize", "arguments": {"id": "stream0"}}
> +{"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 18 tests
>
> OK
> -{"execute": "job-finalize", "arguments": {"id": "commit0"}}
> -{"return": {}}
> -{"data": {"id": "commit0", "type": "commit"}, "event": "BLOCK_JOB_PENDING", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
> -{"data": {"device": "commit0", "len": 3145728, "offset": 3145728, "speed": 0, "type": "commit"}, "event": "BLOCK_JOB_COMPLETED", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
> -{"execute": "job-finalize", "arguments": {"id": "stream0"}}
> -{"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"}}
> -{"execute": "job-finalize", "arguments": {"id": "stream0"}}
> -{"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"}}
> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
> index 661d7f93bf..b97cc2fab2 100644
> --- a/tests/qemu-iotests/iotests.py
> +++ b/tests/qemu-iotests/iotests.py
> @@ -35,6 +35,13 @@ from collections import OrderedDict
> sys.path.append(os.path.join(os.path.dirname(__file__), '..', '..', 'python'))
> from qemu import qtest
>
> +# Use this logger for logging messages directly from the iotests module
> +logger = logging.getLogger(__name__)
> +logger.addHandler(logging.NullHandler())
> +
> +# Use this logger for messages that ought to be used for diff output.
> +test_logger = logging.getLogger('.'.join((__name__, 'iotest')))
> +test_logger.addHandler(logging.NullHandler())
>
> # This will not work if arguments contain spaces but is necessary if we
> # want to support the override options that ./check supports.
> @@ -343,10 +350,10 @@ def log(msg, filters=[], indent=None):
> separators = (', ', ': ') if indent is None else (',', ': ')
> # Don't sort if it's already sorted
> do_sort = not isinstance(msg, OrderedDict)
> - print(json.dumps(msg, sort_keys=do_sort,
> - indent=indent, separators=separators))
> + test_logger.info(json.dumps(msg, sort_keys=do_sort,
> + indent=indent, separators=separators))
> else:
> - print(msg)
> + test_logger.info(msg)
>
> class Timeout:
> def __init__(self, seconds, errmsg = "Timeout"):
> @@ -559,7 +566,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.
>
> @@ -572,7 +579,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.
> """
> @@ -590,8 +596,7 @@ class VM(qtest.QEMUQtestMachine):
> while True:
> ev = filter_qmp_event(self.events_wait(events))
> if ev['event'] != 'JOB_STATUS_CHANGE':
> - if use_log:
> - log(ev)
> + log(ev)
> continue
> status = ev['data']['status']
> if status == 'aborting':
> @@ -599,24 +604,16 @@ 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 == '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:
> + else:
> self.qmp_log('job-finalize', id=job)
> - else:
> - self.qmp('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
>
> @@ -949,6 +946,7 @@ def execute_setup_common(supported_fmts=[],
> if debug:
> sys.argv.remove('-d')
> logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
> + logger.debug("iotests debugging messages active")
>
> return debug
>
> @@ -961,14 +959,25 @@ def execute_test(test_function=None, *args, **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(test_function, *args, **kwargs)
>
> # This is called from unittest style iotests
>
On 8/29/19 2:34 PM, Philippe Mathieu-Daudé wrote:
> On 8/21/19 1:52 AM, John Snow wrote:
>> 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.
>> ---
>> tests/qemu-iotests/030 | 4 +--
>> tests/qemu-iotests/245 | 1 +
>> tests/qemu-iotests/245.out | 24 +++++++++---------
>> tests/qemu-iotests/iotests.py | 47 +++++++++++++++++++++--------------
>> 4 files changed, 43 insertions(+), 33 deletions(-)
>>
>> diff --git a/tests/qemu-iotests/030 b/tests/qemu-iotests/030
>> index 1b69f318c6..a382cb430b 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/245 b/tests/qemu-iotests/245
>> index bc1ceb9792..3bc29acb33 100644
>> --- a/tests/qemu-iotests/245
>> +++ b/tests/qemu-iotests/245
>> @@ -1000,4 +1000,5 @@ class TestBlockdevReopen(iotests.QMPTestCase):
>> self.reopen(opts, {'backing': 'hd2'})
>>
>> if __name__ == '__main__':
>> + iotests.activate_logging()
>> iotests.main(supported_fmts=["qcow2"])
>
> Why not use:
>
> iotests.script_main(iotests.main, supported_fmts=['qcow2')
>
Well, that'd call iotests.execute_test twice and it'd perform setup
twice, too.
Usually, we want logging on for "script-style" tests, but we want
logging off for unittest-style ones. This test has opted to use both.
(Or more likely: just wanted to use run_job and just dealt with the
extramodal output.)
OK; we can turn on logging as we see fit.
--js
© 2016 - 2026 Red Hat, Inc.