Message ID | 20190820235243.26092-5-jsnow@redhat.com |
---|---|
State | New |
Headers | show |
Series | iotests: use python logging | expand |
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
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