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

[Kevin Wolf]

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 <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 ...?
> > 
> > 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