Re: [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log()
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
>> ---
>> 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 '(? 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
Re: [Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log()
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
> ---
> 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 '(? 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":
[Qemu-devel] [PATCH 2/2] iotests: use python logging for iotests.log()
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')))
