| Message ID | 20200331000014.11581-15-jsnow@redhat.com |
|---|---|
| State | New |
| Headers | show |
| Series | iotests: use python logging | expand |
Am 31.03.2020 um 02:00 hat John Snow geschrieben: > 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 <jsnow@redhat.com> > Reviewed-by: Max Reitz <mreitz@redhat.com> Should we enable logger if -d is given? Previously we had: $ ./check -d -T -raw 281 [...] 281 not run: not suitable for this image format: raw 281 not run [15:39:03] [15:39:04] not suitable for this image format: raw Not run: 281 After this series, the first line of output from notrun() is missing. Not that I think it's important to have the line, but as long as we bother to call logger.warning(), I thought that maybe we want to be able to actually see the effect of it somehwere? Kevin
On 3/31/20 9:44 AM, Kevin Wolf wrote: > Am 31.03.2020 um 02:00 hat John Snow geschrieben: >> 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 <jsnow@redhat.com> >> Reviewed-by: Max Reitz <mreitz@redhat.com> > > Should we enable logger if -d is given? > > Previously we had: > > $ ./check -d -T -raw 281 > [...] > 281 not run: not suitable for this image format: raw > 281 not run [15:39:03] [15:39:04] not suitable for this image format: raw > Not run: 281 > > After this series, the first line of output from notrun() is missing. > Not that I think it's important to have the line, but as long as we > bother to call logger.warning(), I thought that maybe we want to be able > to actually see the effect of it somehwere? > > Kevin > Uh, okay. So this is weirder than I thought it was going to be! So, if you move the debug configuration up above the _verify calls, you'll see the message printed out to the debug stream: DEBUG:qemu.iotests:iotests debugging messages active WARNING:qemu.iotests:281 not run: not suitable for this image format: raw ...but if you omit the `-d` flag, the message vanishes into a black hole. Did it always work like that ...? (I'll keep looking. --js)
Am 14.05.2020 um 08:24 hat John Snow geschrieben: > On 3/31/20 9:44 AM, Kevin Wolf wrote: > > Am 31.03.2020 um 02:00 hat John Snow geschrieben: > >> 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 <jsnow@redhat.com> > >> Reviewed-by: Max Reitz <mreitz@redhat.com> > > > > Should we enable logger if -d is given? > > > > Previously we had: > > > > $ ./check -d -T -raw 281 > > [...] > > 281 not run: not suitable for this image format: raw > > 281 not run [15:39:03] [15:39:04] not suitable for this image format: raw > > Not run: 281 > > > > After this series, the first line of output from notrun() is missing. > > Not that I think it's important to have the line, but as long as we > > bother to call logger.warning(), I thought that maybe we want to be able > > to actually see the effect of it somehwere? > > > > Kevin > > > > Uh, okay. So this is weirder than I thought it was going to be! > > So, if you move the debug configuration up above the _verify calls, > you'll see the message printed out to the debug stream: > > DEBUG:qemu.iotests:iotests debugging messages active > WARNING:qemu.iotests:281 not run: not suitable for this image format: raw > > ...but if you omit the `-d` flag, the message vanishes into a black > hole. Did it always work like that ...? Yes, this is how it used to work. It's a result of ./check only printing the test output with -d, and such log messages are basically just test output. And I think it's exactly what we want: Without -d, you want only the summary, i.e. a single line that says "pass", "fail" or "notrun", potentially with a small note at the end of the line, but that's it. Kevin
On 5/14/20 6:06 AM, Kevin Wolf wrote: > Am 14.05.2020 um 08:24 hat John Snow geschrieben: >> On 3/31/20 9:44 AM, Kevin Wolf wrote: >>> Am 31.03.2020 um 02:00 hat John Snow geschrieben: >>>> 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 <jsnow@redhat.com> >>>> Reviewed-by: Max Reitz <mreitz@redhat.com> >>> >>> Should we enable logger if -d is given? >>> >>> Previously we had: >>> >>> $ ./check -d -T -raw 281 >>> [...] >>> 281 not run: not suitable for this image format: raw >>> 281 not run [15:39:03] [15:39:04] not suitable for this image format: raw >>> Not run: 281 >>> >>> After this series, the first line of output from notrun() is missing. >>> Not that I think it's important to have the line, but as long as we >>> bother to call logger.warning(), I thought that maybe we want to be able >>> to actually see the effect of it somehwere? >>> >>> Kevin >>> >> >> Uh, okay. So this is weirder than I thought it was going to be! >> >> So, if you move the debug configuration up above the _verify calls, >> you'll see the message printed out to the debug stream: >> >> DEBUG:qemu.iotests:iotests debugging messages active >> WARNING:qemu.iotests:281 not run: not suitable for this image format: raw >> >> ...but if you omit the `-d` flag, the message vanishes into a black >> hole. Did it always work like that ...? > > Yes, this is how it used to work. It's a result of ./check only printing > the test output with -d, and such log messages are basically just test > output. > > And I think it's exactly what we want: Without -d, you want only the > summary, i.e. a single line that says "pass", "fail" or "notrun", > potentially with a small note at the end of the line, but that's it. > OK, maybe. So I guess what happens here is that if you don't use -d, the output gets redirected to file, and that file is summarily deleted. Your phrase "but as long as we bother to call logger.warning(), I thought that maybe we want to be able to actually see the effect of it somewhere" stuck with me -- I think you're right. I kind of do expect that if I call a function called warning() that it's gonna do some damage. principle of least surprise, etc. So two things: (1) Maybe the iotest logger ought to always use stderr, and we should see any calls to warning() or error() even when debugging is off. (2) These skip notifications are not warnings, they are informational and can be disabled when `-d` is omitted. (Especially because they are represented through another channel.) --js (I'll send the fixup for the simpler thing first, and you can take or leave the second thing.)
Am 14.05.2020 um 21:54 hat John Snow geschrieben: > > > On 5/14/20 6:06 AM, Kevin Wolf wrote: > > Am 14.05.2020 um 08:24 hat John Snow geschrieben: > >> On 3/31/20 9:44 AM, Kevin Wolf wrote: > >>> Am 31.03.2020 um 02:00 hat John Snow geschrieben: > >>>> 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 <jsnow@redhat.com> > >>>> Reviewed-by: Max Reitz <mreitz@redhat.com> > >>> > >>> Should we enable logger if -d is given? > >>> > >>> Previously we had: > >>> > >>> $ ./check -d -T -raw 281 > >>> [...] > >>> 281 not run: not suitable for this image format: raw > >>> 281 not run [15:39:03] [15:39:04] not suitable for this image format: raw > >>> Not run: 281 > >>> > >>> After this series, the first line of output from notrun() is missing. > >>> Not that I think it's important to have the line, but as long as we > >>> bother to call logger.warning(), I thought that maybe we want to be able > >>> to actually see the effect of it somehwere? > >>> > >>> Kevin > >>> > >> > >> Uh, okay. So this is weirder than I thought it was going to be! > >> > >> So, if you move the debug configuration up above the _verify calls, > >> you'll see the message printed out to the debug stream: > >> > >> DEBUG:qemu.iotests:iotests debugging messages active > >> WARNING:qemu.iotests:281 not run: not suitable for this image format: raw > >> > >> ...but if you omit the `-d` flag, the message vanishes into a black > >> hole. Did it always work like that ...? > > > > Yes, this is how it used to work. It's a result of ./check only printing > > the test output with -d, and such log messages are basically just test > > output. > > > > And I think it's exactly what we want: Without -d, you want only the > > summary, i.e. a single line that says "pass", "fail" or "notrun", > > potentially with a small note at the end of the line, but that's it. > > OK, maybe. So I guess what happens here is that if you don't use -d, the > output gets redirected to file, and that file is summarily deleted. > > Your phrase "but as long as we bother to call logger.warning(), I > thought that maybe we want to be able to actually see the effect of it > somewhere" stuck with me -- I think you're right. Yes, and I still think the same, but "somewhere" includes -d for me. I just wouldn't want it to be effectively dead code that doesn't have an effect no matter what options you use. > I kind of do expect that if I call a function called warning() that it's > gonna do some damage. principle of least surprise, etc. > > So two things: > > (1) Maybe the iotest logger ought to always use stderr, and we should > see any calls to warning() or error() even when debugging is off. Even stderr is considered test output. This is not an accident, but we actually want to test that we get error messages. So this wouldn't change the visible result. Maybe what we should do is print a small notice "warnings/errors were logged" at the end of the line like we do for notrun, so you know you should rerun the test with -d? But anyway, why would we ever get error() with a test that passes? > (2) These skip notifications are not warnings, they are informational > and can be disabled when `-d` is omitted. (Especially because they are > represented through another channel.) > > (I'll send the fixup for the simpler thing first, and you can take or > leave the second thing.) I would be perfectly happy with just a fix that makes the messages appear again with -d. Kevin
On 5/15/20 5:03 AM, Kevin Wolf wrote: > Am 14.05.2020 um 21:54 hat John Snow geschrieben: >> >> >> On 5/14/20 6:06 AM, Kevin Wolf wrote: >>> Am 14.05.2020 um 08:24 hat John Snow geschrieben: >>>> On 3/31/20 9:44 AM, Kevin Wolf wrote: >>>>> Am 31.03.2020 um 02:00 hat John Snow geschrieben: >>>>>> 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 <jsnow@redhat.com> >>>>>> Reviewed-by: Max Reitz <mreitz@redhat.com> >>>>> >>>>> Should we enable logger if -d is given? >>>>> >>>>> Previously we had: >>>>> >>>>> $ ./check -d -T -raw 281 >>>>> [...] >>>>> 281 not run: not suitable for this image format: raw >>>>> 281 not run [15:39:03] [15:39:04] not suitable for this image format: raw >>>>> Not run: 281 >>>>> >>>>> After this series, the first line of output from notrun() is missing. >>>>> Not that I think it's important to have the line, but as long as we >>>>> bother to call logger.warning(), I thought that maybe we want to be able >>>>> to actually see the effect of it somehwere? >>>>> >>>>> Kevin >>>>> >>>> >>>> Uh, okay. So this is weirder than I thought it was going to be! >>>> >>>> So, if you move the debug configuration up above the _verify calls, >>>> you'll see the message printed out to the debug stream: >>>> >>>> DEBUG:qemu.iotests:iotests debugging messages active >>>> WARNING:qemu.iotests:281 not run: not suitable for this image format: raw >>>> >>>> ...but if you omit the `-d` flag, the message vanishes into a black >>>> hole. Did it always work like that ...? >>> >>> Yes, this is how it used to work. It's a result of ./check only printing >>> the test output with -d, and such log messages are basically just test >>> output. >>> >>> And I think it's exactly what we want: Without -d, you want only the >>> summary, i.e. a single line that says "pass", "fail" or "notrun", >>> potentially with a small note at the end of the line, but that's it. >> >> OK, maybe. So I guess what happens here is that if you don't use -d, the >> output gets redirected to file, and that file is summarily deleted. >> >> Your phrase "but as long as we bother to call logger.warning(), I >> thought that maybe we want to be able to actually see the effect of it >> somewhere" stuck with me -- I think you're right. > > Yes, and I still think the same, but "somewhere" includes -d for me. I > just wouldn't want it to be effectively dead code that doesn't have an > effect no matter what options you use. > >> I kind of do expect that if I call a function called warning() that it's >> gonna do some damage. principle of least surprise, etc. >> >> So two things: >> >> (1) Maybe the iotest logger ought to always use stderr, and we should >> see any calls to warning() or error() even when debugging is off. > > Even stderr is considered test output. This is not an accident, but we > actually want to test that we get error messages. So this wouldn't > change the visible result. > I learned this after I wrote this idea and went to go implement it. Makes sense, if we want to compare stderr messages to known failure cases. Oops. > Maybe what we should do is print a small notice "warnings/errors were > logged" at the end of the line like we do for notrun, so you know you > should rerun the test with -d? > > But anyway, why would we ever get error() with a test that passes? > Bad tests? :) >> (2) These skip notifications are not warnings, they are informational >> and can be disabled when `-d` is omitted. (Especially because they are >> represented through another channel.) >> >> (I'll send the fixup for the simpler thing first, and you can take or >> leave the second thing.) > > I would be perfectly happy with just a fix that makes the messages > appear again with -d. > > Kevin > Yup, just wanted to take a look at it and give it proper consideration. Patch 1/3 from that series ought to do the trick all by itself.
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 -{"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 fd8cb36622..56179605a9 100644 --- a/tests/qemu-iotests/iotests.py +++ b/tests/qemu-iotests/iotests.py @@ -42,6 +42,14 @@ QMPResponse = Dict[str, Any] +# 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') + + faulthandler.enable() # This will not work if arguments contain spaces but is necessary if we @@ -384,9 +392,9 @@ def log(msg: Msg, if isinstance(msg, (dict, list)): # Don't sort if it's already sorted do_sort = not isinstance(msg, OrderedDict) - print(json.dumps(msg, sort_keys=do_sort, indent=indent)) + test_logger.info(json.dumps(msg, sort_keys=do_sort, indent=indent)) else: - print(msg) + test_logger.info(msg) class Timeout: def __init__(self, seconds, errmsg="Timeout"): @@ -608,7 +616,7 @@ def qmp_log(self, cmd, filters=(), indent=None, **kwargs): # 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. @@ -621,7 +629,6 @@ def run_job(self, job, auto_finalize=True, auto_dismiss=False, 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. """ @@ -639,8 +646,7 @@ def run_job(self, job, auto_finalize=True, auto_dismiss=False, while True: ev = filter_qmp_event(self.events_wait(events, timeout=wait)) if ev['event'] != 'JOB_STATUS_CHANGE': - if use_log: - log(ev) + log(ev) continue status = ev['data']['status'] if status == 'aborting': @@ -648,29 +654,18 @@ def run_job(self, job, auto_finalize=True, auto_dismiss=False, 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 == 'ready': - if use_log: - self.qmp_log('job-complete', id=job) - else: - self.qmp('job-complete', id=job) + self.qmp_log('job-complete', id=job) 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) - elif use_log: + else: self.qmp_log('job-finalize', id=job) - else: - self.qmp('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 @@ -990,7 +985,7 @@ def notrun(reason): seq = os.path.basename(sys.argv[0]) open('%s/%s.notrun' % (output_dir, seq), 'w').write(reason + '\n') - print('%s not run: %s' % (seq, reason)) + logger.warning("%s not run: %s", seq, reason) sys.exit(0) def case_notrun(reason): @@ -1182,6 +1177,7 @@ def execute_setup_common(supported_fmts: Sequence[str] = (), if debug: sys.argv.remove('-d') logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN)) + logger.debug("iotests debugging messages active") return debug @@ -1194,14 +1190,25 @@ def execute_test(*args, test_function=None, **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(*args, test_function=test_function, **kwargs) # This is called from unittest style iotests