Re: [Qemu-devel] [PATCH v5 5/5] iotests: use python logging for iotests.log()

[Vladimir Sementsov-Ogievskiy]

18.09.2019 2:45, 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.

Interesting, how can that be? pre-patch logging goes to stdout of test-case
and after-patch logging goes to stdout of test-case.. What's the difference
from tests/qemu-iotest/check point of view?

> 
> 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 | 49 +++++++++++++++++++++--------------
>   4 files changed, 44 insertions(+), 34 deletions(-)
> 
> diff --git a/tests/qemu-iotests/030 b/tests/qemu-iotests/030
> index f3766f2a81..01aa96ed16 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 41218d5f1d..eba2157cff 100644
> --- a/tests/qemu-iotests/245
> +++ b/tests/qemu-iotests/245
> @@ -1000,5 +1000,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 e28d75e018..5a501f0529 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
>   
> @@ -809,7 +806,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):
> @@ -954,6 +951,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
>   
> @@ -966,14 +964,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)

Hmm, it seems this formatter is default behavior, and it's not necessary to
create and set it..

> +    test_logger.addHandler(handler)

possibly, we want to remove old handler (null), as it's not needed anymore.

> +    test_logger.setLevel(logging.INFO)

Should it be DEBUG if -d given?

> +    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
> 

anyway, it seems OK for me as is:

Reviewed-by: Vladimir Sementsov-Ogievskiy <address@hidden>


-- 
Best regards,
Vladimir