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

[John Snow <jsnow@redhat.com>]

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.