Re: [PATCH v6 6/9] iotests: use python logging for iotests.log()

2020-03-03 Thread John Snow 



On 2/27/20 9:21 AM, Max Reitz wrote:
> On 27.02.20 01:06, 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.
>>
>> 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 | 50 +--
>>  4 files changed, 45 insertions(+), 34 deletions(-)
> 
> [...]
> 
>> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
>> index b02d7932fa..60c4c7f736 100644
>> --- a/tests/qemu-iotests/iotests.py
>> +++ b/tests/qemu-iotests/iotests.py
>> @@ -35,6 +35,14 @@
>>  
>>  assert sys.version_info >= (3, 6)
>>  
>> +# Use this logger for logging messages directly from the iotests module
>> +logger = logging.getLogger('qemu.iotests')
>> +logger.addHandler(logging.NullHandler())
> 
> Hm, I never see another handler added to this, so how can these messages
> actually be printed?  Will enabling debug mode somehow make all loggers
> print everything?
> 

Implicit fallback to root logger which handles them when the root logger
is configured, which happens when logging.basicConfig is called.

>> +# Use this logger for messages that ought to be used for diff output.
>> +test_logger = logging.getLogger('qemu.iotests.diff_io')
> 
> Also, why does logger get a null handler and this by default does not?
> I’m asking because test_logger makes it look like you don’t necessarily
> need a handler for output to be silently discarded.
> 
> Max
> 

It's a library trick. By adding a null handler at `qemu.iotests` I add a
default handler to everything produced by iotests. When logging is not
configured, this stops messages from being printed -- there IS a default
"nonconfigured" logging behavior and this stops it.

What I learned since the last time I wrote this patchset is that you
only need a NullHandler at some particular root, so "qemu.iotests"
suffices. "qemu.iotests.diff_io" is a child of that other logger.

>>  # This will not work if arguments contain spaces but is necessary if we
>>  # want to support the override options that ./check supports.
>>  qemu_img_args = [os.environ.get('QEMU_IMG_PROG', 'qemu-img')]
> 

-- 
—js

Re: [PATCH v6 6/9] iotests: use python logging for iotests.log()

2020-02-27 Thread Max Reitz 
On 27.02.20 01:06, 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.
> 
> 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 | 50 +--
>  4 files changed, 45 insertions(+), 34 deletions(-)

[...]

> diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
> index b02d7932fa..60c4c7f736 100644
> --- a/tests/qemu-iotests/iotests.py
> +++ b/tests/qemu-iotests/iotests.py
> @@ -35,6 +35,14 @@
>  
>  assert sys.version_info >= (3, 6)
>  
> +# Use this logger for logging messages directly from the iotests module
> +logger = logging.getLogger('qemu.iotests')
> +logger.addHandler(logging.NullHandler())

Hm, I never see another handler added to this, so how can these messages
actually be printed?  Will enabling debug mode somehow make all loggers
print everything?

> +# Use this logger for messages that ought to be used for diff output.
> +test_logger = logging.getLogger('qemu.iotests.diff_io')

Also, why does logger get a null handler and this by default does not?
I’m asking because test_logger makes it look like you don’t necessarily
need a handler for output to be silently discarded.

Max

>  # This will not work if arguments contain spaces but is necessary if we
>  # want to support the override options that ./check supports.
>  qemu_img_args = [os.environ.get('QEMU_IMG_PROG', 'qemu-img')]



signature.asc
Description: OpenPGP digital signature

[PATCH v6 6/9] iotests: use python logging for iotests.log()

2020-02-26 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.

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 | 50 +--
 4 files changed, 45 insertions(+), 34 deletions(-)

diff --git a/tests/qemu-iotests/030 b/tests/qemu-iotests/030
index aa911d266a..104e3cee1b 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 489bf78bd0..edb40a4ae8 100755
--- a/tests/qemu-iotests/245
+++ b/tests/qemu-iotests/245
@@ -1002,5 +1002,6 @@ class TestBlockdevReopen(iotests.QMPTestCase):
 self.reopen(opts, {'backing': 'hd2'})
 
 if __name__ == '__main__':
+iotests.activate_logging()
 iotests.main(supported_fmts=["qcow2"],
  supported_protocols=["file"])
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 b02d7932fa..60c4c7f736 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -35,6 +35,14 @@
 
 assert sys.version_info >= (3, 6)
 
+# Use this logger for logging messages directly from the iotests module
+logger = logging.getLogger('qemu.iotests')
+logger.addHandler(logging.NullHandler())
+
+# Use this logger for messages that ought to be used for diff output.
+test_logger = logging.getLogger('qemu.iotests.diff_io')
+
+
 # This will not work if arguments contain spaces but is necessa