From patchwork Fri Jul 26 22:52:01 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: John Snow X-Patchwork-Id: 11061989 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id BE7D96C5 for ; Fri, 26 Jul 2019 22:55:25 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id B1C5D28B68 for ; Fri, 26 Jul 2019 22:55:25 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id A5FA428B6B; Fri, 26 Jul 2019 22:55:25 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-5.2 required=2.0 tests=BAYES_00,MAILING_LIST_MULTI, RCVD_IN_DNSWL_MED autolearn=ham version=3.3.1 Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 02E5D28B68 for ; Fri, 26 Jul 2019 22:55:25 +0000 (UTC) Received: from localhost ([::1]:43610 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.86_2) (envelope-from ) id 1hr97U-0001LV-9x for patchwork-qemu-devel@patchwork.kernel.org; Fri, 26 Jul 2019 18:55:24 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:55558) by lists.gnu.org with esmtp (Exim 4.86_2) (envelope-from ) id 1hr97L-0000wg-Gl for qemu-devel@nongnu.org; Fri, 26 Jul 2019 18:55:17 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1hr976-0001Jp-K3 for qemu-devel@nongnu.org; Fri, 26 Jul 2019 18:55:06 -0400 Received: from mx1.redhat.com ([209.132.183.28]:60718) by eggs.gnu.org with esmtps (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:32) (Exim 4.71) (envelope-from ) id 1hr96O-0000Pz-Sh; Fri, 26 Jul 2019 18:54:21 -0400 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 702A985543; Fri, 26 Jul 2019 22:52:06 +0000 (UTC) Received: from probe.bos.redhat.com (dhcp-17-211.bos.redhat.com [10.18.17.211]) by smtp.corp.redhat.com (Postfix) with ESMTP id B8BB35C6E2; Fri, 26 Jul 2019 22:52:05 +0000 (UTC) From: John Snow To: qemu-devel@nongnu.org, qemu-block@nongnu.org Date: Fri, 26 Jul 2019 18:52:01 -0400 Message-Id: <20190726225201.10561-3-jsnow@redhat.com> In-Reply-To: <20190726225201.10561-1-jsnow@redhat.com> References: <20190726225201.10561-1-jsnow@redhat.com> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.11 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.28]); Fri, 26 Jul 2019 22:52:06 +0000 (UTC) X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] X-Received-From: 209.132.183.28 Subject: [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log() X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Kevin Wolf , John Snow , ehabkost@redhat.com, Max Reitz Errors-To: qemu-devel-bounces+patchwork-qemu-devel=patchwork.kernel.org@nongnu.org Sender: "Qemu-devel" X-Virus-Scanned: ClamAV using ClamSMTP 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. (No, I have no idea why output on 245 changed. I really don't.) Signed-off-by: John Snow --- tests/qemu-iotests/030 | 4 +-- tests/qemu-iotests/245 | 1 + tests/qemu-iotests/245.out | 24 +++++++++--------- tests/qemu-iotests/iotests.py | 48 ++++++++++++++++++++--------------- 4 files changed, 43 insertions(+), 34 deletions(-) diff --git a/tests/qemu-iotests/030 b/tests/qemu-iotests/030 index 1b69f318c6..a382cb430b 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 bc1ceb9792..3bc29acb33 100644 --- a/tests/qemu-iotests/245 +++ b/tests/qemu-iotests/245 @@ -1000,4 +1000,5 @@ class TestBlockdevReopen(iotests.QMPTestCase): self.reopen(opts, {'backing': 'hd2'}) if __name__ == '__main__': + iotests.activate_logging() iotests.main(supported_fmts=["qcow2"]) 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 5e9b2989dd..d55ca864eb 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,15 @@ 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) - if use_log: - self.qmp_log('job-finalize', id=job) - else: - self.qmp('job-finalize', id=job) + self.qmp_log('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 @@ -924,6 +920,7 @@ def execute_setup_common(supported_fmts=[], supported_oses=['linux'], output = io.BytesIO() logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN)) + logger.debug("iotests debugging messages active") return output, verbosity, debug def execute_test(test_function=None, *args, **kwargs): @@ -935,14 +932,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 + # 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