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 <js...@redhat.com>
>> ---
>> 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 '(?<!get_)log\(' [0-9]*)
> 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