Re: [PATCH v2] tests/qtest/qom-test: Do not print tested properties by default

[Daniel P . Berrangé]

On Tue, Jan 17, 2023 at 11:32:42AM +0100, Thomas Huth wrote:
> On 17/01/2023 11.23, Peter Maydell wrote:
> > On Mon, 16 Jan 2023 at 16:55, Peter Maydell <peter.maydell@linaro.org> 
> > wrote:
> > > 
> > > On Thu, 15 Dec 2022 at 15:30, Thomas Huth <thuth@redhat.com> wrote:
> > > > 
> > > > We're still running into the problem that some logs are cut in the
> > > > gitlab-CI since they got too big. The biggest part of the log is
> > > > still the output of the qom-test. Let's stop printing the properties
> > > > by default to get to a saner size here. The full output can still
> > > > be enabled by setting V=2 (or higher) in the environment.
> > > > 
> > > > Signed-off-by: Thomas Huth <thuth@redhat.com>
> > > > ---
> > > >   v2: Use atoi() to do proper checking of the verbosity level
> > > 
> > > Applied to master in the hope of improving the CI logs; thanks.
> > 
> > Looks like we can still hit the gitlab log limit in some
> > cases, even with this patch; here's an example job:
> > https://gitlab.com/qemu-project/qemu/-/jobs/3610621992
> 
> Ok, too bad ... three ideas to improve this situation further:
> 
> - We could shut up those "Obtaining properties of" lines by
>   default

Yes, they add little value in debugging test results from CI.

There's plenty of other largely useless junk printed too

Pages and pages of:

Looking for expected file 'tests/data/acpi/q35/FACP.memhp'
Looking for expected file 'tests/data/acpi/q35/FACP'
Using expected file 'tests/data/acpi/q35/FACP'
Looking for expected file 'tests/data/acpi/q35/APIC.memhp'
Looking for expected file 'tests/data/acpi/q35/APIC'
...

Something random that looks like bad text data

▶ 166/619 /ptimer/oneshot 
policy=no_immediate_����������������������������������������������������������������...snip....�������������


And what i think is test float being overly verbose

  >> Testing f16_le_quiet

  46464 tests total.

    10000
    20000
    30000
    40000
  46464 tests performed.

Could be written as

  >> Testing f16_le_quiet: 46464 tests total .... OK

(one '.' for each 10,000 tests run, before final 'OK' is printed)

> - Stop running the tests with "V=1"

Definitely not, the info about individual test cases being
executed is absolutely critical when a test hangs, so we can
narrow down what was running when it hung.

I think the key is that when we pass 'V=1' to tests, we want to
see lists of individual test cases being run, but we don't want
to see adhoc debugging output. The latter should either be deleted
if useless, or hidden by a getenv("QEMU_TESTS_DEBUG") check

> - Instead of doing "cat meson-logs/testlog.txt" in the CI
>   scripts, we switch to "tail -n 1000 meson-logs/testlog.txt"
>   instead

Tail requires that it has consumed the entire doc before it prints
anything. This in turn implies that the test suite has finished.
IOW, we'll get zero output if it hangs IIUC.

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|