[PATCH v6 6/9] iotests: use python logging for iotests.log()

[John Snow]

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.

Signed-off-by: John Snow <address@hidden>
---
 tests/qemu-iotests/030        |  4 +--
 tests/qemu-iotests/245        |  1 +
 tests/qemu-iotests/245.out    | 24 ++++++++---------
 tests/qemu-iotests/iotests.py | 50 +++++++++++++++++++++--------------
 4 files changed, 45 insertions(+), 34 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/245 b/tests/qemu-iotests/245
index 489bf78bd0..edb40a4ae8 100755
--- a/tests/qemu-iotests/245
+++ b/tests/qemu-iotests/245
@@ -1002,5 +1002,6 @@ class TestBlockdevReopen(iotests.QMPTestCase):
         self.reopen(opts, {'backing': 'hd2'})
 
 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 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 b02d7932fa..60c4c7f736 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -35,6 +35,14 @@
 
 assert sys.version_info >= (3, 6)
 
+# 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')
+
+
 # This will not work if arguments contain spaces but is necessary if we
 # want to support the override options that ./check supports.
 qemu_img_args = [os.environ.get('QEMU_IMG_PROG', 'qemu-img')]
@@ -361,10 +369,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"):
@@ -578,7 +586,7 @@ def qmp_log(self, cmd, filters=(), indent=None, **kwargs):
 
     # 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.
 
@@ -591,7 +599,6 @@ def run_job(self, job, auto_finalize=True, 
auto_dismiss=False,
                              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.
         """
@@ -609,8 +616,7 @@ def run_job(self, job, auto_finalize=True, 
auto_dismiss=False,
         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':
@@ -618,26 +624,18 @@ def run_job(self, job, auto_finalize=True, 
auto_dismiss=False,
                 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':
                 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:
+                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
 
@@ -953,7 +951,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):
@@ -1136,6 +1134,7 @@ def execute_setup_common(supported_fmts: Collection[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
 
@@ -1148,14 +1147,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.21.1