From nobody Wed Apr 16 08:02:48 2025 Delivered-To: importer@patchew.org Received-SPF: pass (zoho.com: domain of gnu.org designates 208.118.235.17 as permitted sender) client-ip=208.118.235.17; envelope-from=qemu-devel-bounces+importer=patchew.org@nongnu.org; helo=lists.gnu.org; Authentication-Results: mx.zohomail.com; spf=pass (zoho.com: domain of gnu.org designates 208.118.235.17 as permitted sender) smtp.mailfrom=qemu-devel-bounces+importer=patchew.org@nongnu.org; dmarc=fail(p=none dis=none) header.from=redhat.com Return-Path: Received: from lists.gnu.org (lists.gnu.org [208.118.235.17]) by mx.zohomail.com with SMTPS id 1528728790562877.5115781551235; Mon, 11 Jun 2018 07:53:10 -0700 (PDT) Received: from localhost ([::1]:49311 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1fSOBx-0000Dx-Q5 for importer@patchew.org; Mon, 11 Jun 2018 10:53:09 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:53400) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1fSNmm-00050S-NM for qemu-devel@nongnu.org; Mon, 11 Jun 2018 10:27:11 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1fSNml-00020T-5w for qemu-devel@nongnu.org; Mon, 11 Jun 2018 10:27:08 -0400 Received: from mx3-rdu2.redhat.com ([66.187.233.73]:54520 helo=mx1.redhat.com) by eggs.gnu.org with esmtps (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:32) (Exim 4.71) (envelope-from ) id 1fSNmc-0001vr-Vi; Mon, 11 Jun 2018 10:26:59 -0400 Received: from smtp.corp.redhat.com (int-mx04.intmail.prod.int.rdu2.redhat.com [10.11.54.4]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 941DB4022905; Mon, 11 Jun 2018 14:26:58 +0000 (UTC) Received: from localhost (unknown [10.40.205.155]) by smtp.corp.redhat.com (Postfix) with ESMTPS id 3E702202698A; Mon, 11 Jun 2018 14:26:58 +0000 (UTC) From: Max Reitz To: qemu-block@nongnu.org Date: Mon, 11 Jun 2018 16:26:05 +0200 Message-Id: <20180611142611.6609-24-mreitz@redhat.com> In-Reply-To: <20180611142611.6609-1-mreitz@redhat.com> References: <20180611142611.6609-1-mreitz@redhat.com> X-Scanned-By: MIMEDefang 2.78 on 10.11.54.4 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.11.55.6]); Mon, 11 Jun 2018 14:26:58 +0000 (UTC) X-Greylist: inspected by milter-greylist-4.5.16 (mx1.redhat.com [10.11.55.6]); Mon, 11 Jun 2018 14:26:58 +0000 (UTC) for IP:'10.11.54.4' DOMAIN:'int-mx04.intmail.prod.int.rdu2.redhat.com' HELO:'smtp.corp.redhat.com' FROM:'mreitz@redhat.com' RCPT:'' X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] [fuzzy] X-Received-From: 66.187.233.73 Subject: [Qemu-devel] [PULL 23/29] iotests: Fix 219's timing X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Kevin Wolf , Peter Maydell , qemu-devel@nongnu.org, Max Reitz Errors-To: qemu-devel-bounces+importer=patchew.org@nongnu.org Sender: "Qemu-devel" X-ZohoMail: RSF_0 Z_629925259 SPT_0 Content-Transfer-Encoding: quoted-printable MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" 219 has two issues that may lead to sporadic failure, both of which are the result of issuing query-jobs too early after a job has been modified. This can then lead to different results based on whether the modification has taken effect already or not. First, query-jobs is issued right after the job has been created. Besides its current progress possibly being in any random state (which has already been taken care of), its total progress too is basically arbitrary, because the job may not yet have been able to determine it. This patch addresses this by just filtering the total progress, like what has been done for the current progress already. However, for more clarity, the filtering is changed to replace the values by a string 'FILTERED' instead of deleting them. Secondly, query-jobs is issued right after a job has been resumed. The job may or may not yet have had the time to actually perform any I/O, and thus its current progress may or may not have advanced. To make sure it has indeed advanced (which is what the reference output already assumes), keep querying it until it has. Signed-off-by: Max Reitz Message-id: 20180606190628.8170-1-mreitz@redhat.com Reviewed-by: Eric Blake Signed-off-by: Max Reitz --- tests/qemu-iotests/219 | 26 ++++++++++++++++++++------ tests/qemu-iotests/219.out | 10 +++++----- 2 files changed, 25 insertions(+), 11 deletions(-) diff --git a/tests/qemu-iotests/219 b/tests/qemu-iotests/219 index 898a26eef0..c03bbdb294 100755 --- a/tests/qemu-iotests/219 +++ b/tests/qemu-iotests/219 @@ -42,11 +42,24 @@ def test_pause_resume(vm): iotests.log(vm.qmp(pause_cmd, **{pause_arg: 'job0'})) pause_wait(vm, 'job0') iotests.log(iotests.filter_qmp_event(vm.event_wait('JOB_STATUS= _CHANGE'))) - iotests.log(vm.qmp('query-jobs')) + result =3D vm.qmp('query-jobs') + iotests.log(result) + + old_progress =3D result['return'][0]['current-progress'] + total_progress =3D result['return'][0]['total-progress'] =20 iotests.log(vm.qmp(resume_cmd, **{resume_arg: 'job0'})) iotests.log(iotests.filter_qmp_event(vm.event_wait('JOB_STATUS= _CHANGE'))) - iotests.log(vm.qmp('query-jobs')) + if old_progress < total_progress: + # Wait for the job to advance + while result['return'][0]['current-progress'] =3D=3D old_p= rogress: + result =3D vm.qmp('query-jobs') + iotests.log(result) + else: + # Already reached the end, so the job cannot advance + # any further; therefore, the query-jobs result can be + # logged immediately + iotests.log(vm.qmp('query-jobs')) =20 def test_job_lifecycle(vm, job, job_args, has_ready=3DFalse): iotests.log('') @@ -58,12 +71,13 @@ def test_job_lifecycle(vm, job, job_args, has_ready=3DF= alse): iotests.log(vm.qmp(job, job_id=3D'job0', **job_args)) =20 # Depending on the storage, the first request may or may not have comp= leted - # yet, so filter out the progress. Later query-job calls don't need the - # filtering because the progress is made deterministic by the block job - # speed + # yet (and the total progress may not have been fully determined yet),= so + # filter out the progress. Later query-job calls don't need the filter= ing + # because the progress is made deterministic by the block job speed result =3D vm.qmp('query-jobs') for j in result['return']: - del j['current-progress'] + j['current-progress'] =3D 'FILTERED' + j['total-progress'] =3D 'FILTERED' iotests.log(result) =20 # undefined -> created -> running diff --git a/tests/qemu-iotests/219.out b/tests/qemu-iotests/219.out index 346801b655..6dc07bc41e 100644 --- a/tests/qemu-iotests/219.out +++ b/tests/qemu-iotests/219.out @@ -3,7 +3,7 @@ Launching VM... =20 Starting block job: drive-mirror (auto-finalize: True; auto-dismiss: True) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'= job0', u'type': u'mirror'}]} +{u'return': [{u'status': u'running', u'current-progress': 'FILTERED', u'to= tal-progress': 'FILTERED', u'id': u'job0', u'type': u'mirror'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} =20 @@ -93,7 +93,7 @@ Waiting for PENDING state... =20 Starting block job: drive-backup (auto-finalize: True; auto-dismiss: True) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'= job0', u'type': u'backup'}]} +{u'return': [{u'status': u'running', u'current-progress': 'FILTERED', u'to= tal-progress': 'FILTERED', u'id': u'job0', u'type': u'backup'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} =20 @@ -144,7 +144,7 @@ Waiting for PENDING state... =20 Starting block job: drive-backup (auto-finalize: True; auto-dismiss: False) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'= job0', u'type': u'backup'}]} +{u'return': [{u'status': u'running', u'current-progress': 'FILTERED', u'to= tal-progress': 'FILTERED', u'id': u'job0', u'type': u'backup'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} =20 @@ -203,7 +203,7 @@ Waiting for PENDING state... =20 Starting block job: drive-backup (auto-finalize: False; auto-dismiss: True) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'= job0', u'type': u'backup'}]} +{u'return': [{u'status': u'running', u'current-progress': 'FILTERED', u'to= tal-progress': 'FILTERED', u'id': u'job0', u'type': u'backup'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} =20 @@ -262,7 +262,7 @@ Waiting for PENDING state... =20 Starting block job: drive-backup (auto-finalize: False; auto-dismiss: Fals= e) {u'return': {}} -{u'return': [{u'status': u'running', u'total-progress': 4194304, u'id': u'= job0', u'type': u'backup'}]} +{u'return': [{u'status': u'running', u'current-progress': 'FILTERED', u'to= tal-progress': 'FILTERED', u'id': u'job0', u'type': u'backup'}]} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'created', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} {u'timestamp': {u'seconds': 'SECS', u'microseconds': 'USECS'}, u'data': {u= 'status': u'running', u'id': u'job0'}, u'event': u'JOB_STATUS_CHANGE'} =20 --=20 2.17.1