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

2019-08-29 Thread John Snow 



On 8/29/19 2:34 PM, Philippe Mathieu-Daudé wrote:
> On 8/21/19 1:52 AM, 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.
>> ---
>>  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 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"])
> 
> Why not use:
> 
>iotests.script_main(iotests.main, supported_fmts=['qcow2')
> 

Well, that'd call iotests.execute_test twice and it'd perform setup
twice, too.

Usually, we want logging on for "script-style" tests, but we want
logging off for unittest-style ones. This test has opted to use both.

(Or more likely: just wanted to use run_job and just dealt with the
extramodal output.)

OK; we can turn on logging as we see fit.

--js

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

2019-08-29 Thread Philippe Mathieu-Daudé 
On 8/21/19 1:52 AM, 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.
> ---
>  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 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"])

Why not use:

   iotests.script_main(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 661d7f93bf..b97cc2fab2 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

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

2019-08-20 Thread John Snow 
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.
---
 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 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 661d7f93bf..b97cc2fab2 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')))