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

[Kevin Wolf]

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.

Kevin