qemu-devel.nongnu.org archive mirror
 help / color / mirror / Atom feed
* [Qemu-devel] [PATCH 0/2] iotests: use python logging
@ 2019-07-26 22:51 John Snow
  2019-07-26 22:52 ` [Qemu-devel] [PATCH 1/2] iotests: add script_initialize John Snow
  2019-07-26 22:52 ` [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log() John Snow
  0 siblings, 2 replies; 7+ messages in thread
From: John Snow @ 2019-07-26 22:51 UTC (permalink / raw)
  To: qemu-devel, qemu-block; +Cc: Kevin Wolf, John Snow, ehabkost, Max Reitz

Based-on: https://github.com/jnsnow/qemu/tree/bitmaps

This is a quick hack-em-up of what it might look like to use python
logging to enable output conditionally on iotests.log(). We unify an
initialization call (which also enables debugging output for those tests
with -d) and then make the switch inside of iotests.

It might help with needing to add logged/unlogged versions.

Depends on my bitmaps branch, because of the iotests refactoring I have
done there.

John Snow (2):
  iotests: add script_initialize
  iotests: use python logging for iotests.log()

 tests/qemu-iotests/030        |  4 +--
 tests/qemu-iotests/149        |  3 +-
 tests/qemu-iotests/194        |  3 +-
 tests/qemu-iotests/202        |  3 +-
 tests/qemu-iotests/203        |  3 +-
 tests/qemu-iotests/206        |  2 +-
 tests/qemu-iotests/208        |  2 +-
 tests/qemu-iotests/216        |  3 +-
 tests/qemu-iotests/218        |  2 +-
 tests/qemu-iotests/219        |  2 +-
 tests/qemu-iotests/222        |  5 ++-
 tests/qemu-iotests/224        |  3 +-
 tests/qemu-iotests/228        |  3 +-
 tests/qemu-iotests/234        |  3 +-
 tests/qemu-iotests/235        |  4 +--
 tests/qemu-iotests/236        |  2 +-
 tests/qemu-iotests/238        |  2 ++
 tests/qemu-iotests/242        |  2 +-
 tests/qemu-iotests/245        |  1 +
 tests/qemu-iotests/245.out    | 24 ++++++-------
 tests/qemu-iotests/246        |  2 +-
 tests/qemu-iotests/248        |  2 +-
 tests/qemu-iotests/254        |  2 +-
 tests/qemu-iotests/255        |  2 +-
 tests/qemu-iotests/256        |  2 +-
 tests/qemu-iotests/iotests.py | 67 ++++++++++++++++++++++-------------
 26 files changed, 83 insertions(+), 70 deletions(-)

-- 
2.21.0



^ permalink raw reply	[flat|nested] 7+ messages in thread
* [Qemu-devel] [PATCH 1/2] iotests: add script_initialize
  2019-07-26 22:51 [Qemu-devel] [PATCH 0/2] iotests: use python logging John Snow
@ 2019-07-26 22:52 ` John Snow
  2019-07-29  0:07   ` Eduardo Habkost
  2019-07-26 22:52 ` [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log() John Snow
  1 sibling, 1 reply; 7+ messages in thread
From: John Snow @ 2019-07-26 22:52 UTC (permalink / raw)
  To: qemu-devel, qemu-block; +Cc: Kevin Wolf, John Snow, ehabkost, Max Reitz

Like script_main, but doesn't require a single point of entry.
Replace all existing initialization sections with this drop-in replacement.

This brings debug support to all existing script-style iotests.

Note: supported_oses=['linux'] was omitted, as it is a default argument.
Signed-off-by: John Snow <jsnow@redhat.com>
---
 tests/qemu-iotests/149        |  3 +--
 tests/qemu-iotests/194        |  3 +--
 tests/qemu-iotests/202        |  3 +--
 tests/qemu-iotests/203        |  3 +--
 tests/qemu-iotests/206        |  2 +-
 tests/qemu-iotests/208        |  2 +-
 tests/qemu-iotests/216        |  3 +--
 tests/qemu-iotests/218        |  2 +-
 tests/qemu-iotests/219        |  2 +-
 tests/qemu-iotests/222        |  5 ++---
 tests/qemu-iotests/224        |  3 +--
 tests/qemu-iotests/228        |  3 +--
 tests/qemu-iotests/234        |  3 +--
 tests/qemu-iotests/235        |  4 ++--
 tests/qemu-iotests/236        |  2 +-
 tests/qemu-iotests/238        |  2 ++
 tests/qemu-iotests/242        |  2 +-
 tests/qemu-iotests/246        |  2 +-
 tests/qemu-iotests/248        |  2 +-
 tests/qemu-iotests/254        |  2 +-
 tests/qemu-iotests/255        |  2 +-
 tests/qemu-iotests/256        |  2 +-
 tests/qemu-iotests/iotests.py | 19 +++++++++++++++----
 23 files changed, 40 insertions(+), 36 deletions(-)

diff --git a/tests/qemu-iotests/149 b/tests/qemu-iotests/149
index 4f363f295f..9fa97966c5 100755
--- a/tests/qemu-iotests/149
+++ b/tests/qemu-iotests/149
@@ -383,8 +383,7 @@ def test_once(config, qemu_img=False):
 
 
 # Obviously we only work with the luks image format
-iotests.verify_image_format(supported_fmts=['luks'])
-iotests.verify_platform()
+iotests.script_initialize(supported_fmts=['luks'])
 
 # We need sudo in order to run cryptsetup to create
 # dm-crypt devices. This is safe to use on any
diff --git a/tests/qemu-iotests/194 b/tests/qemu-iotests/194
index d746ab1e21..c8aeb6d0e4 100755
--- a/tests/qemu-iotests/194
+++ b/tests/qemu-iotests/194
@@ -21,8 +21,7 @@
 
 import iotests
 
-iotests.verify_image_format(supported_fmts=['qcow2', 'qed', 'raw'])
-iotests.verify_platform(['linux'])
+iotests.script_initialize(supported_fmts=['qcow2', 'qed', 'raw'])
 
 with iotests.FilePath('source.img') as source_img_path, \
      iotests.FilePath('dest.img') as dest_img_path, \
diff --git a/tests/qemu-iotests/202 b/tests/qemu-iotests/202
index 581ca34d79..1271ac9459 100755
--- a/tests/qemu-iotests/202
+++ b/tests/qemu-iotests/202
@@ -24,8 +24,7 @@
 
 import iotests
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
-iotests.verify_platform(['linux'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 with iotests.FilePath('disk0.img') as disk0_img_path, \
      iotests.FilePath('disk1.img') as disk1_img_path, \
diff --git a/tests/qemu-iotests/203 b/tests/qemu-iotests/203
index 4874a1a0d8..c40fe231ea 100755
--- a/tests/qemu-iotests/203
+++ b/tests/qemu-iotests/203
@@ -24,8 +24,7 @@
 
 import iotests
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
-iotests.verify_platform(['linux'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 with iotests.FilePath('disk0.img') as disk0_img_path, \
      iotests.FilePath('disk1.img') as disk1_img_path, \
diff --git a/tests/qemu-iotests/206 b/tests/qemu-iotests/206
index 5bb738bf23..23ff2f624b 100755
--- a/tests/qemu-iotests/206
+++ b/tests/qemu-iotests/206
@@ -23,7 +23,7 @@
 import iotests
 from iotests import imgfmt
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 def blockdev_create(vm, options):
     result = vm.qmp_log('blockdev-create',
diff --git a/tests/qemu-iotests/208 b/tests/qemu-iotests/208
index 1e202388dc..dfce6f9fe4 100755
--- a/tests/qemu-iotests/208
+++ b/tests/qemu-iotests/208
@@ -22,7 +22,7 @@
 
 import iotests
 
-iotests.verify_image_format(supported_fmts=['generic'])
+iotests.script_initialize(supported_fmts=['generic'])
 
 with iotests.FilePath('disk.img') as disk_img_path, \
      iotests.FilePath('disk-snapshot.img') as disk_snapshot_img_path, \
diff --git a/tests/qemu-iotests/216 b/tests/qemu-iotests/216
index 3c0ae54b44..7574bcc09f 100755
--- a/tests/qemu-iotests/216
+++ b/tests/qemu-iotests/216
@@ -23,8 +23,7 @@ import iotests
 from iotests import log, qemu_img, qemu_io_silent
 
 # Need backing file support
-iotests.verify_image_format(supported_fmts=['qcow2', 'qcow', 'qed', 'vmdk'])
-iotests.verify_platform(['linux'])
+iotests.script_initialize(supported_fmts=['qcow2', 'qcow', 'qed', 'vmdk'])
 
 log('')
 log('=== Copy-on-read across nodes ===')
diff --git a/tests/qemu-iotests/218 b/tests/qemu-iotests/218
index 2554d84581..e18e31076b 100755
--- a/tests/qemu-iotests/218
+++ b/tests/qemu-iotests/218
@@ -29,7 +29,7 @@
 import iotests
 from iotests import log, qemu_img, qemu_io_silent
 
-iotests.verify_image_format(supported_fmts=['qcow2', 'raw'])
+iotests.script_initialize(supported_fmts=['qcow2', 'raw'])
 
 
 # Launches the VM, adds two null-co nodes (source and target), and
diff --git a/tests/qemu-iotests/219 b/tests/qemu-iotests/219
index e0c51662c0..9ae27cb04e 100755
--- a/tests/qemu-iotests/219
+++ b/tests/qemu-iotests/219
@@ -21,7 +21,7 @@
 
 import iotests
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 img_size = 4 * 1024 * 1024
 
diff --git a/tests/qemu-iotests/222 b/tests/qemu-iotests/222
index 0ead56d574..6788979ed3 100644
--- a/tests/qemu-iotests/222
+++ b/tests/qemu-iotests/222
@@ -24,9 +24,8 @@
 import iotests
 from iotests import log, qemu_img, qemu_io, qemu_io_silent
 
-iotests.verify_platform(['linux'])
-iotests.verify_image_format(supported_fmts=['qcow2', 'qcow', 'qed', 'vmdk',
-                                            'vhdx', 'raw'])
+iotests.script_initialize(supported_fmts=['qcow2', 'qcow', 'qed', 'vmdk',
+                                          'vhdx', 'raw'])
 
 patterns = [("0x5d", "0",         "64k"),
             ("0xd5", "1M",        "64k"),
diff --git a/tests/qemu-iotests/224 b/tests/qemu-iotests/224
index b4dfaa639f..d0d0c44104 100755
--- a/tests/qemu-iotests/224
+++ b/tests/qemu-iotests/224
@@ -26,8 +26,7 @@ from iotests import log, qemu_img, qemu_io_silent, filter_qmp_testfiles, \
 import json
 
 # Need backing file support (for arbitrary backing formats)
-iotests.verify_image_format(supported_fmts=['qcow2', 'qcow', 'qed'])
-iotests.verify_platform(['linux'])
+iotests.script_initialize(supported_fmts=['qcow2', 'qcow', 'qed'])
 
 
 # There are two variations of this test:
diff --git a/tests/qemu-iotests/228 b/tests/qemu-iotests/228
index 9a50afd205..9785868ab3 100755
--- a/tests/qemu-iotests/228
+++ b/tests/qemu-iotests/228
@@ -25,8 +25,7 @@ from iotests import log, qemu_img, filter_testfiles, filter_imgfmt, \
         filter_qmp_testfiles, filter_qmp_imgfmt
 
 # Need backing file and change-backing-file support
-iotests.verify_image_format(supported_fmts=['qcow2', 'qed'])
-iotests.verify_platform(['linux'])
+iotests.script_initialize(supported_fmts=['qcow2', 'qed'])
 
 
 def log_node_info(node):
diff --git a/tests/qemu-iotests/234 b/tests/qemu-iotests/234
index c4c26bc21e..b72142040b 100755
--- a/tests/qemu-iotests/234
+++ b/tests/qemu-iotests/234
@@ -23,8 +23,7 @@
 import iotests
 import os
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
-iotests.verify_platform(['linux'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 def enable_migration_events(vm, name):
     iotests.log('Enabling migration QMP events on %s...' % name)
diff --git a/tests/qemu-iotests/235 b/tests/qemu-iotests/235
index fedd111fd4..9e88c65b93 100755
--- a/tests/qemu-iotests/235
+++ b/tests/qemu-iotests/235
@@ -27,6 +27,8 @@ sys.path.append(os.path.join(os.path.dirname(__file__), '..', '..', 'python'))
 
 from qemu.machine import QEMUMachine
 
+iotests.script_initialize(supported_fmts=['qcow2'])
+
 # Note:
 # This test was added to check that mirror dead-lock was fixed (see previous
 # commit before this test addition).
@@ -40,8 +42,6 @@ from qemu.machine import QEMUMachine
 
 size = 1 * 1024 * 1024 * 1024
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
-
 disk = file_path('disk')
 
 # prepare source image
diff --git a/tests/qemu-iotests/236 b/tests/qemu-iotests/236
index 79a6381f8e..b88779eb0b 100755
--- a/tests/qemu-iotests/236
+++ b/tests/qemu-iotests/236
@@ -22,7 +22,7 @@
 import iotests
 from iotests import log
 
-iotests.verify_image_format(supported_fmts=['generic'])
+iotests.script_initialize(supported_fmts=['generic'])
 size = 64 * 1024 * 1024
 granularity = 64 * 1024
 
diff --git a/tests/qemu-iotests/238 b/tests/qemu-iotests/238
index e5ac2b2ff8..6e27fb40c2 100755
--- a/tests/qemu-iotests/238
+++ b/tests/qemu-iotests/238
@@ -23,6 +23,8 @@ import os
 import iotests
 from iotests import log
 
+iotests.script_initialize()
+
 virtio_scsi_device = iotests.get_virtio_scsi_device()
 
 vm = iotests.VM()
diff --git a/tests/qemu-iotests/242 b/tests/qemu-iotests/242
index c176e92da6..7c2685b4cc 100755
--- a/tests/qemu-iotests/242
+++ b/tests/qemu-iotests/242
@@ -24,7 +24,7 @@ import struct
 from iotests import qemu_img_create, qemu_io, qemu_img_pipe, \
     file_path, img_info_log, log, filter_qemu_io
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 disk = file_path('disk')
 chunk = 256 * 1024
diff --git a/tests/qemu-iotests/246 b/tests/qemu-iotests/246
index b0997a392f..1d7747d62d 100755
--- a/tests/qemu-iotests/246
+++ b/tests/qemu-iotests/246
@@ -22,7 +22,7 @@
 import iotests
 from iotests import log
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 size = 64 * 1024 * 1024 * 1024
 gran_small = 32 * 1024
 gran_large = 128 * 1024
diff --git a/tests/qemu-iotests/248 b/tests/qemu-iotests/248
index f26b4bb2aa..781b21b227 100755
--- a/tests/qemu-iotests/248
+++ b/tests/qemu-iotests/248
@@ -21,7 +21,7 @@
 import iotests
 from iotests import qemu_img_create, qemu_io, file_path, filter_qmp_testfiles
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 source, target = file_path('source', 'target')
 size = 5 * 1024 * 1024
diff --git a/tests/qemu-iotests/254 b/tests/qemu-iotests/254
index 09584f3f7d..43b40f4f71 100755
--- a/tests/qemu-iotests/254
+++ b/tests/qemu-iotests/254
@@ -21,7 +21,7 @@
 import iotests
 from iotests import qemu_img_create, file_path, log
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 disk, top = file_path('disk', 'top')
 size = 1024 * 1024
diff --git a/tests/qemu-iotests/255 b/tests/qemu-iotests/255
index 3632d507d0..ff16402268 100755
--- a/tests/qemu-iotests/255
+++ b/tests/qemu-iotests/255
@@ -23,7 +23,7 @@
 import iotests
 from iotests import imgfmt
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 
 def blockdev_create(vm, options):
     result = vm.qmp_log('blockdev-create',
diff --git a/tests/qemu-iotests/256 b/tests/qemu-iotests/256
index c594a43205..d2f9212e5a 100755
--- a/tests/qemu-iotests/256
+++ b/tests/qemu-iotests/256
@@ -23,7 +23,7 @@ import os
 import iotests
 from iotests import log
 
-iotests.verify_image_format(supported_fmts=['qcow2'])
+iotests.script_initialize(supported_fmts=['qcow2'])
 size = 64 * 1024 * 1024
 
 with iotests.FilePath('img0') as img0_path, \
diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
index 727730422f..5e9b2989dd 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -891,9 +891,8 @@ def execute_unittest(output, verbosity, debug):
             sys.stderr.write(re.sub(r'Ran (\d+) tests? in [\d.]+s',
                                     r'Ran \1 tests', output.getvalue()))
 
-def execute_test(test_function=None,
-                 supported_fmts=[], supported_oses=['linux'],
-                 supported_cache_modes=[], unsupported_fmts=[]):
+def execute_setup_common(supported_fmts=[], supported_oses=['linux'],
+                         supported_cache_modes=[], unsupported_fmts=[]):
     """Run either unittest or script-style tests."""
 
     # We are using TEST_DIR and QEMU_DEFAULT_MACHINE as proxies to
@@ -925,16 +924,28 @@ def execute_test(test_function=None,
             output = io.BytesIO()
 
     logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
+    return output, verbosity, debug
 
+def execute_test(test_function=None, *args, **kwargs):
+    """Run either unittest or script-style tests."""
+
+    unittest_args = execute_setup_common(*args, **kwargs)
     if not test_function:
-        execute_unittest(output, verbosity, debug)
+        execute_unittest(*unittest_args)
     else:
         test_function()
 
+# 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."""
+    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"""
     execute_test(test_function, *args, **kwargs)
 
+# This is called from unittest style iotests
 def main(*args, **kwargs):
     """Run tests using the unittest framework"""
     execute_test(None, *args, **kwargs)
-- 
2.21.0



^ permalink raw reply related	[flat|nested] 7+ messages in thread
* [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log()
  2019-07-26 22:51 [Qemu-devel] [PATCH 0/2] iotests: use python logging John Snow
  2019-07-26 22:52 ` [Qemu-devel] [PATCH 1/2] iotests: add script_initialize John Snow
@ 2019-07-26 22:52 ` John Snow
  2019-07-28 23:36   ` Eduardo Habkost
  1 sibling, 1 reply; 7+ messages in thread
From: John Snow @ 2019-07-26 22:52 UTC (permalink / raw)
  To: qemu-devel, qemu-block; +Cc: Kevin Wolf, John Snow, ehabkost, Max Reitz

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 <jsnow@redhat.com>
---
 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
-- 
2.21.0



^ permalink raw reply related	[flat|nested] 7+ messages in thread
* Re: [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log()
  2019-07-26 22:52 ` [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log() John Snow
@ 2019-07-28 23:36   ` Eduardo Habkost
  2019-07-29 15:43     ` John Snow
  0 siblings, 1 reply; 7+ messages in thread
From: Eduardo Habkost @ 2019-07-28 23:36 UTC (permalink / raw)
  To: John Snow; +Cc: Kevin Wolf, qemu-devel, qemu-block, Max Reitz

On Fri, Jul 26, 2019 at 06:52:01PM -0400, 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.
> 
> (No, I have no idea why output on 245 changed. I really don't.)

I believe this happens because the logging StreamHandler will
flush the stream at every call.

I see the same output reordering on 245 if I add a
sys.stdout.flush() call to iotests.log(), or if I change
iotests.main() to use sys.stdout for the unittest runner output.

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

So, this one is the only run_job() caller specifying
use_log=False.  It doesn't call activate_logging() anywhere, so
it seems OK.

However, we need to ensure all the other run_job() callers will
actually enable logging.  The remaining run_job() callers are:
206 207 210 211 212 213 237 245 255 256.

These look OK:
206:iotests.script_initialize(supported_fmts=['qcow2'])
245:    iotests.activate_logging()
255:iotests.script_initialize(supported_fmts=['qcow2'])
256:iotests.script_initialize(supported_fmts=['qcow2'])
257:    iotests.script_main(main, supported_fmts=['qcow2'])

These don't seem to call activate_logging() anywhere:
207 210 211 212 213 237.

What about other scripts calling log() that aren't calling activate_logging()?
Let's see:

  $ git grep -LE 'script_main|script_initialize|activate_logging' \
       $(grep -lP '(?<!get_)log\(' [0-9]*)
  207
  210
  211
  212
  213
  237
  $ 


I didn't run all of these test cases, but I can see that 210 is
now failing:

  $ ./check -luks 210
  QEMU          -- "/home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/../../x86_64-softmmu/qemu-system-x86_64" -nodefaults -machine accel=qtest
  QEMU_IMG      -- "/home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/../../qemu-img"
  QEMU_IO       -- "/home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/../../qemu-io"  --cache writeback
  QEMU_NBD      -- "/home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/../../qemu-nbd"
  IMGFMT        -- luks (iter-time=10)
  IMGPROTO      -- file

  TEST_DIR      -- /home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/scratch
  SOCKET_SCM_HELPER -- /home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/socket_scm_helper
  
  210      fail       [20:20:37] [20:21:00]      (last: 22s)   output mismatch (see 210.out.bad)
  --- /home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/210.out 2019-07-28 18:38:18.040555415 -0300
  +++ /home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/210.out.bad     2019-07-28 20:20:37.398971280 -0300
  @@ -1,231 +0,0 @@
  -=== Successful image creation (defaults) ===
  -
  -{"execute": "blockdev-create", "arguments": {"job-id": "job0", "options": {"driver": "file", "filename": "TEST_DIR/PID-t.luks", "size": 0}}}
  [...]


As most test cases require logging to be enabled, my suggestion
is to activate logging by default and provide a
disable_test_logging() function that can be used by 030.


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

-- 
Eduardo


^ permalink raw reply	[flat|nested] 7+ messages in thread
* Re: [Qemu-devel] [PATCH 1/2] iotests: add script_initialize
  2019-07-26 22:52 ` [Qemu-devel] [PATCH 1/2] iotests: add script_initialize John Snow
@ 2019-07-29  0:07   ` Eduardo Habkost
  2019-07-29 20:19     ` John Snow
  0 siblings, 1 reply; 7+ messages in thread
From: Eduardo Habkost @ 2019-07-29  0:07 UTC (permalink / raw)
  To: John Snow; +Cc: Kevin Wolf, qemu-devel, qemu-block, Max Reitz

On Fri, Jul 26, 2019 at 06:52:00PM -0400, John Snow wrote:
> Like script_main, but doesn't require a single point of entry.
> Replace all existing initialization sections with this drop-in replacement.
> 
> This brings debug support to all existing script-style iotests.
> 
> Note: supported_oses=['linux'] was omitted, as it is a default argument.
> Signed-off-by: John Snow <jsnow@redhat.com>
[...]

Looks good overall, I just have one comment:


> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
> index 727730422f..5e9b2989dd 100644
> --- a/tests/qemu-iotests/iotests.py
> +++ b/tests/qemu-iotests/iotests.py
> @@ -891,9 +891,8 @@ def execute_unittest(output, verbosity, debug):
>              sys.stderr.write(re.sub(r'Ran (\d+) tests? in [\d.]+s',
>                                      r'Ran \1 tests', output.getvalue()))
>  
> -def execute_test(test_function=None,
> -                 supported_fmts=[], supported_oses=['linux'],
> -                 supported_cache_modes=[], unsupported_fmts=[]):
> +def execute_setup_common(supported_fmts=[], supported_oses=['linux'],
> +                         supported_cache_modes=[], unsupported_fmts=[]):
>      """Run either unittest or script-style tests."""
>  
>      # We are using TEST_DIR and QEMU_DEFAULT_MACHINE as proxies to
> @@ -925,16 +924,28 @@ def execute_test(test_function=None,
>              output = io.BytesIO()
>  
>      logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
> +    return output, verbosity, debug

Can't we make this simpler?

What about just returning `debug`, and letting execute_unittest()
take care of `verbosity` and `output`?

>  
> +def execute_test(test_function=None, *args, **kwargs):
> +    """Run either unittest or script-style tests."""
> +
> +    unittest_args = execute_setup_common(*args, **kwargs)
>      if not test_function:
> -        execute_unittest(output, verbosity, debug)
> +        execute_unittest(*unittest_args)
>      else:
>          test_function()
>  
> +# 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."""
> +    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"""
>      execute_test(test_function, *args, **kwargs)
>  
> +# This is called from unittest style iotests
>  def main(*args, **kwargs):
>      """Run tests using the unittest framework"""
>      execute_test(None, *args, **kwargs)
> -- 
> 2.21.0
> 

-- 
Eduardo


^ permalink raw reply	[flat|nested] 7+ messages in thread
* Re: [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log()
  2019-07-28 23:36   ` Eduardo Habkost
@ 2019-07-29 15:43     ` John Snow
  0 siblings, 0 replies; 7+ messages in thread
From: John Snow @ 2019-07-29 15:43 UTC (permalink / raw)
  To: Eduardo Habkost; +Cc: Kevin Wolf, qemu-devel, qemu-block, Max Reitz



On 7/28/19 7:36 PM, Eduardo Habkost wrote:
> On Fri, Jul 26, 2019 at 06:52:01PM -0400, 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.
>>
>> (No, I have no idea why output on 245 changed. I really don't.)
> 
> I believe this happens because the logging StreamHandler will
> flush the stream at every call.
> 

I'm surprised print doesn't flush that often.

> I see the same output reordering on 245 if I add a
> sys.stdout.flush() call to iotests.log(), or if I change
> iotests.main() to use sys.stdout for the unittest runner output.
> 
>>
>> 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 | 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)
> 
> So, this one is the only run_job() caller specifying
> use_log=False.  It doesn't call activate_logging() anywhere, so
> it seems OK.
> 

Yah

> However, we need to ensure all the other run_job() callers will
> actually enable logging.  The remaining run_job() callers are:
> 206 207 210 211 212 213 237 245 255 256.
> 
> These look OK:
> 206:iotests.script_initialize(supported_fmts=['qcow2'])
> 245:    iotests.activate_logging()
> 255:iotests.script_initialize(supported_fmts=['qcow2'])
> 256:iotests.script_initialize(supported_fmts=['qcow2'])
> 257:    iotests.script_main(main, supported_fmts=['qcow2'])
> 
> These don't seem to call activate_logging() anywhere:
> 207 210 211 212 213 237.
> 

There's the quick hack -- not verifying all the non-qcow tests as per usual.

All of these are script-style and should call to script_initialize now
instead. Fixed!

> What about other scripts calling log() that aren't calling activate_logging()?
> Let's see:
> 
>   $ git grep -LE 'script_main|script_initialize|activate_logging' \
>        $(grep -lP '(?<!get_)log\(' [0-9]*)
>   207
>   210
>   211
>   212
>   213
>   237
>   $ 
> 
> 
> I didn't run all of these test cases, but I can see that 210 is
> now failing:
> 
>   $ ./check -luks 210
>   QEMU          -- "/home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/../../x86_64-softmmu/qemu-system-x86_64" -nodefaults -machine accel=qtest
>   QEMU_IMG      -- "/home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/../../qemu-img"
>   QEMU_IO       -- "/home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/../../qemu-io"  --cache writeback
>   QEMU_NBD      -- "/home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/../../qemu-nbd"
>   IMGFMT        -- luks (iter-time=10)
>   IMGPROTO      -- file
> 
>   TEST_DIR      -- /home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/scratch
>   SOCKET_SCM_HELPER -- /home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/socket_scm_helper
>   
>   210      fail       [20:20:37] [20:21:00]      (last: 22s)   output mismatch (see 210.out.bad)
>   --- /home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/210.out 2019-07-28 18:38:18.040555415 -0300
>   +++ /home/ehabkost/rh/proj/virt/qemu/tests/qemu-iotests/210.out.bad     2019-07-28 20:20:37.398971280 -0300
>   @@ -1,231 +0,0 @@
>   -=== Successful image creation (defaults) ===
>   -
>   -{"execute": "blockdev-create", "arguments": {"job-id": "job0", "options": {"driver": "file", "filename": "TEST_DIR/PID-t.luks", "size": 0}}}
>   [...]
> 
> 
> As most test cases require logging to be enabled, my suggestion
> is to activate logging by default and provide a
> disable_test_logging() function that can be used by 030.
> 

Actually, we'd need to disable logging for all the unittest style tests,
so it's probably a wash as to whether we do enable-or-disable by
default. I think disable-by-default has the benefit of making it obvious
when you're missing a call to script_initialize, so I'd like to go that
route.

So basically you have:

A) Unittest - disabled by default
B) script-style - enabled by default

You only need to override this layout for one case -- test 245 -- which
was written to expect run_job logging, which I did in this patch.

I'll send a V2 that mocks this up.

--js


^ permalink raw reply	[flat|nested] 7+ messages in thread
* Re: [Qemu-devel] [PATCH 1/2] iotests: add script_initialize
  2019-07-29  0:07   ` Eduardo Habkost
@ 2019-07-29 20:19     ` John Snow
  0 siblings, 0 replies; 7+ messages in thread
From: John Snow @ 2019-07-29 20:19 UTC (permalink / raw)
  To: Eduardo Habkost; +Cc: Kevin Wolf, qemu-devel, qemu-block, Max Reitz



On 7/28/19 8:07 PM, Eduardo Habkost wrote:
> On Fri, Jul 26, 2019 at 06:52:00PM -0400, John Snow wrote:
>> Like script_main, but doesn't require a single point of entry.
>> Replace all existing initialization sections with this drop-in replacement.
>>
>> This brings debug support to all existing script-style iotests.
>>
>> Note: supported_oses=['linux'] was omitted, as it is a default argument.
>> Signed-off-by: John Snow <jsnow@redhat.com>
> [...]
> 
> Looks good overall, I just have one comment:
> 
> 
>> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
>> index 727730422f..5e9b2989dd 100644
>> --- a/tests/qemu-iotests/iotests.py
>> +++ b/tests/qemu-iotests/iotests.py
>> @@ -891,9 +891,8 @@ def execute_unittest(output, verbosity, debug):
>>              sys.stderr.write(re.sub(r'Ran (\d+) tests? in [\d.]+s',
>>                                      r'Ran \1 tests', output.getvalue()))
>>  
>> -def execute_test(test_function=None,
>> -                 supported_fmts=[], supported_oses=['linux'],
>> -                 supported_cache_modes=[], unsupported_fmts=[]):
>> +def execute_setup_common(supported_fmts=[], supported_oses=['linux'],
>> +                         supported_cache_modes=[], unsupported_fmts=[]):
>>      """Run either unittest or script-style tests."""
>>  
>>      # We are using TEST_DIR and QEMU_DEFAULT_MACHINE as proxies to
>> @@ -925,16 +924,28 @@ def execute_test(test_function=None,
>>              output = io.BytesIO()
>>  
>>      logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
>> +    return output, verbosity, debug
> 
> Can't we make this simpler?
> 
> What about just returning `debug`, and letting execute_unittest()
> take care of `verbosity` and `output`?
> 

"yes," it turns out. v2 soon.


^ permalink raw reply	[flat|nested] 7+ messages in thread
end of thread, other threads:[~2019-07-29 20:19 UTC | newest]

Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-07-26 22:51 [Qemu-devel] [PATCH 0/2] iotests: use python logging John Snow
2019-07-26 22:52 ` [Qemu-devel] [PATCH 1/2] iotests: add script_initialize John Snow
2019-07-29  0:07   ` Eduardo Habkost
2019-07-29 20:19     ` John Snow
2019-07-26 22:52 ` [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log() John Snow
2019-07-28 23:36   ` Eduardo Habkost
2019-07-29 15:43     ` John Snow

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).