Re: [PATCH v10 14/14] iotests: use python logging for iotests.log()

[John Snow]

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 <address@hidden>
>> Reviewed-by: Max Reitz <address@hidden>
> 
> 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)