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

[John Snow <jsnow@redhat.com>]

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 <jsnow@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