jcs.org / qemu
qemu with hax to log dma reads & writes jcs.org/2018/11/12/vfio
fork atom

iotests: use python logging for iotests.log()

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 <jsnow@redhat.com>
Reviewed-by: Max Reitz <mreitz@redhat.com>
Message-Id: <20200331000014.11581-15-jsnow@redhat.com>
Reviewed-by: Kevin Wolf <kwolf@redhat.com>
Signed-off-by: Max Reitz <mreitz@redhat.com>

authored by

John Snow and committed by
Max Reitz 52ea799e 59c29869

+39 -31
+2 -2
tests/qemu-iotests/030
··· 411 411 result = self.vm.qmp('block-job-set-speed', device='drive0', speed=0) 412 412 self.assert_qmp(result, 'return', {}) 413 413 414 - self.vm.run_job(job='drive0', auto_dismiss=True, use_log=False) 415 - self.vm.run_job(job='node4', auto_dismiss=True, use_log=False) 414 + self.vm.run_job(job='drive0', auto_dismiss=True) 415 + self.vm.run_job(job='node4', auto_dismiss=True) 416 416 self.assert_no_active_block_jobs() 417 417 418 418 # Test a block-stream and a block-commit job in parallel
+1 -1
tests/qemu-iotests/155
··· 188 188 189 189 self.assert_qmp(result, 'return', {}) 190 190 191 - self.vm.run_job('mirror-job', use_log=False, auto_finalize=False, 191 + self.vm.run_job('mirror-job', auto_finalize=False, 192 192 pre_finalize=self.openBacking, auto_dismiss=True) 193 193 194 194 def testFull(self):
+1
tests/qemu-iotests/245
··· 1027 1027 self.run_test_iothreads(None, 'iothread0') 1028 1028 1029 1029 if __name__ == '__main__': 1030 + iotests.activate_logging() 1030 1031 iotests.main(supported_fmts=["qcow2"], 1031 1032 supported_protocols=["file"])
+5 -5
tests/qemu-iotests/245.out
··· 1 - ..................... 2 - ---------------------------------------------------------------------- 3 - Ran 21 tests 4 - 5 - OK 6 1 {"execute": "job-finalize", "arguments": {"id": "commit0"}} 7 2 {"return": {}} 8 3 {"data": {"id": "commit0", "type": "commit"}, "event": "BLOCK_JOB_PENDING", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} ··· 15 10 {"return": {}} 16 11 {"data": {"id": "stream0", "type": "stream"}, "event": "BLOCK_JOB_PENDING", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} 17 12 {"data": {"device": "stream0", "len": 3145728, "offset": 3145728, "speed": 0, "type": "stream"}, "event": "BLOCK_JOB_COMPLETED", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}} 13 + ..................... 14 + ---------------------------------------------------------------------- 15 + Ran 21 tests 16 + 17 + OK
+30 -23
tests/qemu-iotests/iotests.py
··· 42 42 QMPResponse = Dict[str, Any] 43 43 44 44 45 + # Use this logger for logging messages directly from the iotests module 46 + logger = logging.getLogger('qemu.iotests') 47 + logger.addHandler(logging.NullHandler()) 48 + 49 + # Use this logger for messages that ought to be used for diff output. 50 + test_logger = logging.getLogger('qemu.iotests.diff_io') 51 + 52 + 45 53 faulthandler.enable() 46 54 47 55 # This will not work if arguments contain spaces but is necessary if we ··· 385 393 if isinstance(msg, (dict, list)): 386 394 # Don't sort if it's already sorted 387 395 do_sort = not isinstance(msg, OrderedDict) 388 - print(json.dumps(msg, sort_keys=do_sort, indent=indent)) 396 + test_logger.info(json.dumps(msg, sort_keys=do_sort, indent=indent)) 389 397 else: 390 - print(msg) 398 + test_logger.info(msg) 391 399 392 400 class Timeout: 393 401 def __init__(self, seconds, errmsg="Timeout"): ··· 609 617 610 618 # Returns None on success, and an error string on failure 611 619 def run_job(self, job, auto_finalize=True, auto_dismiss=False, 612 - pre_finalize=None, cancel=False, use_log=True, wait=60.0): 620 + pre_finalize=None, cancel=False, wait=60.0): 613 621 """ 614 622 run_job moves a job from creation through to dismissal. 615 623 ··· 622 630 invoked prior to issuing job-finalize, if any. 623 631 :param cancel: Bool. When true, cancels the job after the pre_finalize 624 632 callback. 625 - :param use_log: Bool. When false, does not log QMP messages. 626 633 :param wait: Float. Timeout value specifying how long to wait for any 627 634 event, in seconds. Defaults to 60.0. 628 635 """ ··· 640 647 while True: 641 648 ev = filter_qmp_event(self.events_wait(events, timeout=wait)) 642 649 if ev['event'] != 'JOB_STATUS_CHANGE': 643 - if use_log: 644 - log(ev) 650 + log(ev) 645 651 continue 646 652 status = ev['data']['status'] 647 653 if status == 'aborting': ··· 649 655 for j in result['return']: 650 656 if j['id'] == job: 651 657 error = j['error'] 652 - if use_log: 653 - log('Job failed: %s' % (j['error'])) 658 + log('Job failed: %s' % (j['error'])) 654 659 elif status == 'ready': 655 - if use_log: 656 - self.qmp_log('job-complete', id=job) 657 - else: 658 - self.qmp('job-complete', id=job) 660 + self.qmp_log('job-complete', id=job) 659 661 elif status == 'pending' and not auto_finalize: 660 662 if pre_finalize: 661 663 pre_finalize() 662 - if cancel and use_log: 664 + if cancel: 663 665 self.qmp_log('job-cancel', id=job) 664 - elif cancel: 665 - self.qmp('job-cancel', id=job) 666 - elif use_log: 667 - self.qmp_log('job-finalize', id=job) 668 666 else: 669 - self.qmp('job-finalize', id=job) 667 + self.qmp_log('job-finalize', id=job) 670 668 elif status == 'concluded' and not auto_dismiss: 671 - if use_log: 672 - self.qmp_log('job-dismiss', id=job) 673 - else: 674 - self.qmp('job-dismiss', id=job) 669 + self.qmp_log('job-dismiss', id=job) 675 670 elif status == 'null': 676 671 return error 677 672 ··· 991 986 seq = os.path.basename(sys.argv[0]) 992 987 993 988 open('%s/%s.notrun' % (output_dir, seq), 'w').write(reason + '\n') 994 - print('%s not run: %s' % (seq, reason)) 989 + logger.warning("%s not run: %s", seq, reason) 995 990 sys.exit(0) 996 991 997 992 def case_notrun(reason): ··· 1183 1178 if debug: 1184 1179 sys.argv.remove('-d') 1185 1180 logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN)) 1181 + logger.debug("iotests debugging messages active") 1186 1182 1187 1183 return debug 1188 1184 ··· 1195 1191 else: 1196 1192 test_function() 1197 1193 1194 + def activate_logging(): 1195 + """Activate iotests.log() output to stdout for script-style tests.""" 1196 + handler = logging.StreamHandler(stream=sys.stdout) 1197 + formatter = logging.Formatter('%(message)s') 1198 + handler.setFormatter(formatter) 1199 + test_logger.addHandler(handler) 1200 + test_logger.setLevel(logging.INFO) 1201 + test_logger.propagate = False 1202 + 1198 1203 # This is called from script-style iotests without a single point of entry 1199 1204 def script_initialize(*args, **kwargs): 1200 1205 """Initialize script-style tests without running any tests.""" 1206 + activate_logging() 1201 1207 execute_setup_common(*args, **kwargs) 1202 1208 1203 1209 # This is called from script-style iotests with a single point of entry 1204 1210 def script_main(test_function, *args, **kwargs): 1205 1211 """Run script-style tests outside of the unittest framework""" 1212 + activate_logging() 1206 1213 execute_test(*args, test_function=test_function, **kwargs) 1207 1214 1208 1215 # This is called from unittest style iotests