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

[John Snow <jsnow@redhat.com>]

On 9/18/19 10:52 AM, Vladimir Sementsov-Ogievskiy wrote:
> 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 <jsnow@redhat.com>
>> ---
>>   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..
> 

You might be right; I think it's OK to set it explicitly.

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

Right, it's there as an "event sink" in the case that no caller sets up
a root logger. I'll look into this if/when I pursue an idempotent
enable/disable toggle.

At this point, if there's no major issues, I'd rather get the fiddly
bits checked in before continuing on this cleanup; I can always start
sending some "part 2" patches along this line.

>> +    test_logger.setLevel(logging.INFO)
> 
> Should it be DEBUG if -d given?
> 

There's no reason to yet, because there's no use of the test_logger that
uses debug-level statements. That is, regardless of the "debug level",
we're going to log the same exact things to the diff output.

We COULD complicate this in the future if we wanted to. That is, we can
utilize debug-level loggers and create nnn.out.debug; but there's no
reason to do that yet.

>> +    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 <vsementsov@virtuozzo.com>
> 
> 

Oh, and I forgot to clean up the comment strings, sorry about that...
I'll send a fixup patch.

--js