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

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

[Thomas Huth]

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

 tests/qtest/qom-test.c | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

diff --git a/tests/qtest/qom-test.c b/tests/qtest/qom-test.c
index 13510bc349..d380261f8f 100644
--- a/tests/qtest/qom-test.c
+++ b/tests/qtest/qom-test.c
@@ -14,6 +14,8 @@
 #include "qemu/cutils.h"
 #include "libqtest.h"
 
+static bool verbose;
+
 static void test_properties(QTestState *qts, const char *path, bool recurse)
 {
     char *child_path;
@@ -49,7 +51,9 @@ static void test_properties(QTestState *qts, const char *path, bool recurse)
             }
         } else {
             const char *prop = qdict_get_str(tuple, "name");
-            g_test_message("-> %s", prop);
+            if (verbose) {
+                g_test_message("-> %s", prop);
+            }
             tmp = qtest_qmp(qts,
                             "{ 'execute': 'qom-get',"
                             "  'arguments': { 'path': %s, 'property': %s } }",
@@ -103,6 +107,12 @@ static void add_machine_test_case(const char *mname)
 
 int main(int argc, char **argv)
 {
+    char *v_env = getenv("V");
+
+    if (v_env && atoi(v_env) >= 2) {
+        verbose = true;
+    }
+
     g_test_init(&argc, &argv, NULL);
 
     qtest_cb_for_every_machine(add_machine_test_case, g_test_quick());
-- 
2.31.1

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

[Philippe Mathieu-Daudé]

On 15/12/22 16:30, Thomas Huth 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
> 
>   tests/qtest/qom-test.c | 12 +++++++++++-
>   1 file changed, 11 insertions(+), 1 deletion(-)
Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>

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

[Peter Maydell]

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.

-- PMM

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

[Peter Maydell]

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

thanks
-- PMM

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

[Thomas Huth]

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

- Stop running the tests with "V=1"

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

What do you think?

  Thomas

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 :|

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

[Peter Maydell]

On Tue, 17 Jan 2023 at 10:44, Daniel P. Berrangé <berrange@redhat.com> wrote:
> Something random that looks like bad text data
>
> ▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....�������������

I don't understand this one. The string comes from
tests/unit/ptimer-test.c:add_ptimer_tests() but that
code creates the test string using g_strlcat() and
g_strdup_printf(), so I don't see how it could end
up being junk, especially not at that point in
the string. I guess it's possible something else in
the test is managing to corrupt the g_test test name
strings?

> And what i think is test float being overly verbose

Yes, the float tests are massively over-verbose. This
is a problem not just in the length of the test log
but also in finding the actual cause of a test failure,
because often the float tests were running in parallel
with the failed test and print all their very verbose
output after the failed test output, so you have to
scroll back up for miles to find it.

thanks
-- PMM

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

[Daniel P. Berrangé]

On Tue, Jan 17, 2023 at 11:16:32AM +0000, Peter Maydell wrote:
> On Tue, 17 Jan 2023 at 10:44, Daniel P. Berrangé <berrange@redhat.com> wrote:
> > Something random that looks like bad text data
> >
> > ▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....�������������
> 
> I don't understand this one. The string comes from
> tests/unit/ptimer-test.c:add_ptimer_tests() but that
> code creates the test string using g_strlcat() and
> g_strdup_printf(), so I don't see how it could end
> up being junk, especially not at that point in
> the string. I guess it's possible something else in
> the test is managing to corrupt the g_test test name
> strings?

Actually it looks like something else spewing ����������
a to stderr, and this getting intermixed with stdout from the
test suite.  The test case name isn't corrupt, as I see the
remaining "reload,..." bit that jouins with 'policy=no_immediate_"

Wonder what's responsible for this garbage on stderr...


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 :|

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

[Peter Maydell]

On Tue, 17 Jan 2023 at 12:02, Daniel P. Berrangé <berrange@redhat.com> wrote:
>
> On Tue, Jan 17, 2023 at 11:16:32AM +0000, Peter Maydell wrote:
> > On Tue, 17 Jan 2023 at 10:44, Daniel P. Berrangé <berrange@redhat.com> wrote:
> > > Something random that looks like bad text data
> > >
> > > ▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....�������������
> >
> > I don't understand this one. The string comes from
> > tests/unit/ptimer-test.c:add_ptimer_tests() but that
> > code creates the test string using g_strlcat() and
> > g_strdup_printf(), so I don't see how it could end
> > up being junk, especially not at that point in
> > the string. I guess it's possible something else in
> > the test is managing to corrupt the g_test test name
> > strings?
>
> Actually it looks like something else spewing ����������
> a to stderr, and this getting intermixed with stdout from the
> test suite.  The test case name isn't corrupt, as I see the
> remaining "reload,..." bit that jouins with 'policy=no_immediate_"
>
> Wonder what's responsible for this garbage on stderr...

Mmm.

Also I notice that we could save some output if we can
fix whatever it is that's producing out-of-spec TAP
format and causing this to be printed for every test:

Unknown TAP version. The first line MUST be `TAP version <int>`.
Assuming version 12.

-- PMM

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

[Daniel P. Berrangé]

On Tue, Jan 17, 2023 at 12:22:35PM +0000, Peter Maydell wrote:
> On Tue, 17 Jan 2023 at 12:02, Daniel P. Berrangé <berrange@redhat.com> wrote:
> >
> > On Tue, Jan 17, 2023 at 11:16:32AM +0000, Peter Maydell wrote:
> > > On Tue, 17 Jan 2023 at 10:44, Daniel P. Berrangé <berrange@redhat.com> wrote:
> > > > Something random that looks like bad text data
> > > >
> > > > ▶ 166/619 /ptimer/oneshot policy=no_immediate_����������������������������������������������������������������...snip....�������������
> > >
> > > I don't understand this one. The string comes from
> > > tests/unit/ptimer-test.c:add_ptimer_tests() but that
> > > code creates the test string using g_strlcat() and
> > > g_strdup_printf(), so I don't see how it could end
> > > up being junk, especially not at that point in
> > > the string. I guess it's possible something else in
> > > the test is managing to corrupt the g_test test name
> > > strings?
> >
> > Actually it looks like something else spewing ����������
> > a to stderr, and this getting intermixed with stdout from the
> > test suite.  The test case name isn't corrupt, as I see the
> > remaining "reload,..." bit that jouins with 'policy=no_immediate_"
> >
> > Wonder what's responsible for this garbage on stderr...
> 
> Mmm.
> 
> Also I notice that we could save some output if we can
> fix whatever it is that's producing out-of-spec TAP
> format and causing this to be printed for every test:
> 
> Unknown TAP version. The first line MUST be `TAP version <int>`.
> Assuming version 12.

That's a meson bug caused by this misguided change

  https://github.com/mesonbuild/meson/pull/11186

and suggested to revert

  https://github.com/mesonbuild/meson/pull/11242

Though it seems the meson maintainer prefers their only patch:

  https://github.com/eli-schwartz/meson/commit/f0928378d2246bcf8a81be35c44b1350a549d647

but that's not submitted for merge that I've found.

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 :|

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

[Thomas Huth]

On 17/01/2023 11.44, Daniel P. Berrangé wrote:
> On Tue, Jan 17, 2023 at 11:32:42AM +0100, Thomas Huth wrote:
...
>> - 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.

I was referring to the places where we are dumping the testlog.txt like this:

  make --output-sync -j`nproc` check
    || { cat meson-logs/testlog.txt; exit 1; }

See .gitlab-ci.d/custom-runners/* or .gitlab-ci.d/windows.yml for example. I 
assume it should be ok to switch to "tail" instead of "cat" there?

  Thomas

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

[Daniel P. Berrangé]

On Wed, Jan 18, 2023 at 01:55:49PM +0100, Thomas Huth wrote:
> On 17/01/2023 11.44, Daniel P. Berrangé wrote:
> > On Tue, Jan 17, 2023 at 11:32:42AM +0100, Thomas Huth wrote:
> ...
> > > - 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.
> 
> I was referring to the places where we are dumping the testlog.txt like this:
> 
>  make --output-sync -j`nproc` check
>    || { cat meson-logs/testlog.txt; exit 1; }
> 
> See .gitlab-ci.d/custom-runners/* or .gitlab-ci.d/windows.yml for example. I
> assume it should be ok to switch to "tail" instead of "cat" there?

Yes, it would be OK, bug lets make sure meson-logs/testlog.txt is included
as an artifact published by the job, so we can access the full set if
needed


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 :|

float tests are too verbose (was: [PATCH v2] tests/qtest/qom-test: Do not print tested properties by default)

[Thomas Huth]

On 17/01/2023 11.44, Daniel P. Berrangé wrote:
...
> 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)

Unfortunately, the float tests are included via a git submodule, so the 
source code is not under our direct control here ... has anybody a good idea 
how to get this tackled best?

  Thomas

Re: float tests are too verbose (was: [PATCH v2] tests/qtest/qom-test: Do not print tested properties by default)

[Alex Bennée]

Thomas Huth <thuth@redhat.com> writes:

> On 17/01/2023 11.44, Daniel P. Berrangé wrote:
> ...
>> 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)
>
> Unfortunately, the float tests are included via a git submodule, so
> the source code is not under our direct control here ... has anybody a
> good idea how to get this tackled best?

It is under our control. It is a lightly patched version of the
downstream testfloat package so we can patch it some more.

That said reducing 5 lines to one is hardly a massive reduction. If we
just stopped passing V=1 you would get:

➜  make check-softfloat
  GIT     ui/keycodemapdb meson tests/fp/berkeley-testfloat-3 tests/fp/berkeley-softfloat-3 dtc roms/SLOF
[1/1] Generating qemu-version.h with a custom command (wrapped by meson to capture output)
/usr/bin/python3 -B /home/alex/lsrc/qemu.git/meson/meson.py test  --no-rebuild -t 0  --num-processes 1 --print-errorlogs  --suite softfloat
 1/17 qemu:softfloat+softfloat-conv / fp-test-float-to-float           OK              0.02s
 2/17 qemu:softfloat+softfloat-conv / fp-test-int-to-float             OK              0.01s
 3/17 qemu:softfloat+softfloat-conv / fp-test-uint-to-float            OK              0.01s
 4/17 qemu:softfloat+softfloat-conv / fp-test-float-to-int             OK              0.02s
 5/17 qemu:softfloat+softfloat-conv / fp-test-float-to-uint            OK              0.01s
 6/17 qemu:softfloat+softfloat-conv / fp-test-round-to-integer         OK              0.01s
 7/17 qemu:softfloat+softfloat-compare / fp-test-eq_signaling          OK              0.05s
 8/17 qemu:softfloat+softfloat-compare / fp-test-le                    OK              0.05s
 9/17 qemu:softfloat+softfloat-compare / fp-test-le_quiet              OK              0.05s
10/17 qemu:softfloat+softfloat-compare / fp-test-lt_quiet              OK              0.05s
11/17 qemu:softfloat+softfloat-ops / fp-test-add                       OK              0.58s
12/17 qemu:softfloat+softfloat-ops / fp-test-sub                       OK              0.59s
13/17 qemu:softfloat+softfloat-ops / fp-test-mul                       OK              2.83s
14/17 qemu:softfloat+softfloat-ops / fp-test-div                       OK              2.11s
15/17 qemu:softfloat+softfloat-ops / fp-test-rem                       OK              1.27s
16/17 qemu:softfloat+softfloat-ops / fp-test-sqrt                      OK              0.03s
17/17 qemu:softfloat+softfloat-ops / fp-test-log2                      OK              0.02s


Ok:                 17  
Expected Fail:      0   
Fail:               0   
Unexpected Pass:    0   
Skipped:            0   
Timeout:            0   

Full log written to /home/alex/lsrc/qemu.git/builds/all/meson-logs/testlog.txt

with the testlog being:

wc -l meson-logs/testlog.txt
2553 meson-logs/testlog.txt

>
>  Thomas


-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro