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

[John Snow <jsnow@redhat.com>]

On 9/17/19 7:35 AM, Vladimir Sementsov-Ogievskiy wrote:
> 12.09.2019 3:16, 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.
>>
>> 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 | 47 +++++++++++++++++++++--------------
>>   4 files changed, 43 insertions(+), 33 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()
> 
> or it may be a parameter for main().. But I'm OK with this too, of course.
> 

I think most of the unittest style tests don't need or want logged
output in this way, but we can always do it later if we want.

>>       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 92117a64bc..7e46fb2754 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())
> 
> Still, I see one "print" call left in notrun(). Should it be changed to use logger or test_logger?
> 

Good question...

I guess notrun() writes to the .notrun file, which the main test runner
uses to know not to check the output in stdout as a diff against the
reference output.

The 'check' runner then cats the .notrun file to stdout for the user to see.

the print() is discarded (unless we were in debug mode, and then it was
printed to the screen.)

It seems like a control message for the user, so my guess is that it
ought to be sent to the module-level logger and printed to stderr, actually.

maybe warning-level?

>>   
>>   # 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
> 
> I like this change. Interesting, should we just enable logging in qmp() and
> drop qmp_log() function, to always manage log/don't-log behavior through
> python logger? But this seems to be larger effort, including iotests output
> changes, not for these series.
> 

Yes, that's probably a good idea. One function that always logs, and
where that gets routed to and what happens to it is configured elsewhere.

We can work towards a unified logging story over time.

>>   
>> @@ -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))
> 
> Hmm, interesting, am I right, that before this patch, this logging.basicConfig() line
> is the only use of logging module, and therefore unused?
> 

Oh, I see -- no, actually; this line turns on all of the debugging
statements in included modules too.

basicConfig, when executed *before any other logging statement*, will
create a defaultly-configured handler and logger at the root of the
hierarchy.

When you call basicConfig, you create and enable the root logger. Later,
when qmp.py calls logging.getLogger('QMP'), it attaches itself under the
root logger.

Then, messages will propagate from the QMP logger to the root logger.

So by enabling it here, you actually enable logging everywhere.

> Does it affect all existent loggers (i.e. logger and test_logger)? Hmm, seems not:
> "Does basic configuration for the logging system by creating a StreamHandler with a default Formatter and adding it to the root logger."
> 

You're half-right.

If other loggers *already exist*, basicConfig does nothing. If they
don't, it creates a default handler.

By effect, that default handler allows other loggers to propagate their
messages up to the root and in effect, it enables those loggers.

However, all loggers exist in one tree in a python process; so we can
enable and disable them post-hoc to our liking.

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

Which is what I am doing here.

I create a formatter that does nothing but print the message as-is, and
a handler that routes the message to stdout.

Then I add the formatter to the handler, and the handler to the logger.
I turn on event processing at the INFO level and then turn off propagation.

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