Re: [PATCH v8 11/11] iotests: use python logging for iotests.log()

2020-03-24 Thread Max Reitz
On 17.03.20 01:41, 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.
> 
> 
> An extended note on python logging:

Thanks!

> A NullHandler is added to `qemu.iotests` to stop output from being
> generated if this code is used as a library without configuring logging.
> A NullHandler is only needed at the root, so a duplicate handler is not
> needed for `qemu.iotests.diff_io`.
> 
> When logging is not configured, messages at the 'WARNING' levels or
> above are printed with default settings. The NullHandler stops this from
> occurring, which is considered good hygiene for code used as a library.
> 
> See https://docs.python.org/3/howto/logging.html#library-config
> 
> When logging is actually enabled (always at the behest of an explicit
> call by a client script), a root logger is implicitly created at the
> root, which allows messages to propagate upwards and be handled/emitted
> from the root logger with default settings.
> 
> When we want iotest logging, we attach a handler to the
> qemu.iotests.diff_io logger and disable propagation to avoid possible
> double-printing.
> 
> For more information on python logging infrastructure, I highly
> recommend downloading the pip package `logging_tree`, which provides
> convenient visualizations of the hierarchical logging configuration
> under different circumstances.
> 
> See https://pypi.org/project/logging_tree/ for more information.
> 
> Signed-off-by: John Snow 
> ---
>  tests/qemu-iotests/030|  4 +--
>  tests/qemu-iotests/155|  2 +-
>  tests/qemu-iotests/245|  1 +
>  tests/qemu-iotests/245.out| 24 
>  tests/qemu-iotests/iotests.py | 53 ---
>  5 files changed, 46 insertions(+), 38 deletions(-)

Reviewed-by: Max Reitz 



signature.asc
Description: OpenPGP digital signature


[PATCH v8 11/11] iotests: use python logging for iotests.log()

2020-03-16 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.


An extended note on python logging:

A NullHandler is added to `qemu.iotests` to stop output from being
generated if this code is used as a library without configuring logging.
A NullHandler is only needed at the root, so a duplicate handler is not
needed for `qemu.iotests.diff_io`.

When logging is not configured, messages at the 'WARNING' levels or
above are printed with default settings. The NullHandler stops this from
occurring, which is considered good hygiene for code used as a library.

See https://docs.python.org/3/howto/logging.html#library-config

When logging is actually enabled (always at the behest of an explicit
call by a client script), a root logger is implicitly created at the
root, which allows messages to propagate upwards and be handled/emitted
from the root logger with default settings.

When we want iotest logging, we attach a handler to the
qemu.iotests.diff_io logger and disable propagation to avoid possible
double-printing.

For more information on python logging infrastructure, I highly
recommend downloading the pip package `logging_tree`, which provides
convenient visualizations of the hierarchical logging configuration
under different circumstances.

See https://pypi.org/project/logging_tree/ for more information.

Signed-off-by: John Snow 
---
 tests/qemu-iotests/030|  4 +--
 tests/qemu-iotests/155|  2 +-
 tests/qemu-iotests/245|  1 +
 tests/qemu-iotests/245.out| 24 
 tests/qemu-iotests/iotests.py | 53 ---
 5 files changed, 46 insertions(+), 38 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/155 b/tests/qemu-iotests/155
index 571bce9de4..cb371d4649 100755
--- a/tests/qemu-iotests/155
+++ b/tests/qemu-iotests/155
@@ -188,7 +188,7 @@ class MirrorBaseClass(BaseClass):
 
 self.assert_qmp(result, 'return', {})
 
-self.vm.run_job('mirror-job', use_log=False, auto_finalize=False,
+self.vm.run_job('mirror-job', auto_finalize=False,
 pre_finalize=self.openBacking, auto_dismiss=True)
 
 def testFull(self):
diff --git a/tests/qemu-iotests/245 b/tests/qemu-iotests/245
index 1001275a44..4f5f0bb901 100755
--- a/tests/qemu-iotests/245
+++ b/tests/qemu-iotests/245
@@ -1027,5 +1027,6 @@ class TestBlockdevReopen(iotests.QMPTestCase):
 self.run_test_iothreads(None, 'iothread0')
 
 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 682b93394d..4b33dcaf5c 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 21 tests
 
 OK