[PATCH 0/2] ci: improve debuggability of I/O tests

[PATCH 0/2] ci: improve debuggability of I/O tests

[Daniel P. Berrangé]

Currently with the TAP harness we see essentially no useful information
about the I/O tests execution. To pick a random job:

  https://gitlab.com/qemu-project/qemu/-/jobs/2429330423

All that we get is this:

  184/204 qemu:block / qemu-iotests qcow2  OK  309.10s   116 subtests passed

The full details are in a testlog.txt file that isn't accessible. This
series publishes that as an artifact. It further tweaks the TAP runner
to print out when it is about to run a test, so we get a record of what
was running, if the test harness gets terminated abnormally/prematurely

Daniel P. Berrangé (2):
  tests/qemu-iotests: print intent to run a test in TAP mode
  .gitlab-ci.d: export meson testlog.txt as an artifact

 .gitlab-ci.d/buildtest-template.yml | 12 ++++++++++--
 tests/qemu-iotests/testrunner.py    |  3 +++
 2 files changed, 13 insertions(+), 2 deletions(-)

-- 
2.35.1

[PATCH 1/2] tests/qemu-iotests: print intent to run a test in TAP mode

[Daniel P. Berrangé]

When running I/O tests using TAP output mode, we get a single TAP test
with a sub-test reported for each I/O test that is run. The output looks
something like this:

 1..123
 ok qcow2 011
 ok qcow2 012
 ok qcow2 013
 ok qcow2 217
 ...

If everything runs or fails normally this is fine, but periodically we
have been seeing the test harness abort early before all 123 tests have
been run, just leaving a fairly useless message like

  TAP parsing error: Too few tests run (expected 123, got 107)

we have no idea which tests were running at the time the test harness
abruptly exited. This change causes us to print a message about our
intent to run each test, so we have a record of what is active at the
time the harness exits abnormally.

 1..123
 # running qcow2 011
 ok qcow2 011
 # running qcow2 012
 ok qcow2 012
 # running qcow2 013
 ok qcow2 013
 # running qcow2 217
 ok qcow2 217
 ...

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qemu-iotests/testrunner.py | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/tests/qemu-iotests/testrunner.py b/tests/qemu-iotests/testrunner.py
index aae70a8341..dc871b7caf 100644
--- a/tests/qemu-iotests/testrunner.py
+++ b/tests/qemu-iotests/testrunner.py
@@ -361,6 +361,9 @@ def run_test(self, test: str,
                                      starttime=start,
                                      lasttime=last_el,
                                      end = '\n' if mp else '\r')
+        else:
+            testname = os.path.basename(test)
+            print(f'# running {self.env.imgfmt} {testname}')
 
         res = self.do_run_test(test, mp)
 
-- 
2.35.1

Re: [PATCH 1/2] tests/qemu-iotests: print intent to run a test in TAP mode

[Thomas Huth]

On 09/05/2022 14.41, Daniel P. Berrangé wrote:
> When running I/O tests using TAP output mode, we get a single TAP test
> with a sub-test reported for each I/O test that is run. The output looks
> something like this:
> 
>   1..123
>   ok qcow2 011
>   ok qcow2 012
>   ok qcow2 013
>   ok qcow2 217
>   ...
> 
> If everything runs or fails normally this is fine, but periodically we
> have been seeing the test harness abort early before all 123 tests have
> been run, just leaving a fairly useless message like
> 
>    TAP parsing error: Too few tests run (expected 123, got 107)
> 
> we have no idea which tests were running at the time the test harness
> abruptly exited. This change causes us to print a message about our
> intent to run each test, so we have a record of what is active at the
> time the harness exits abnormally.
> 
>   1..123
>   # running qcow2 011
>   ok qcow2 011
>   # running qcow2 012
>   ok qcow2 012
>   # running qcow2 013
>   ok qcow2 013
>   # running qcow2 217
>   ok qcow2 217
>   ...
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qemu-iotests/testrunner.py | 3 +++
>   1 file changed, 3 insertions(+)
> 
> diff --git a/tests/qemu-iotests/testrunner.py b/tests/qemu-iotests/testrunner.py
> index aae70a8341..dc871b7caf 100644
> --- a/tests/qemu-iotests/testrunner.py
> +++ b/tests/qemu-iotests/testrunner.py
> @@ -361,6 +361,9 @@ def run_test(self, test: str,
>                                        starttime=start,
>                                        lasttime=last_el,
>                                        end = '\n' if mp else '\r')
> +        else:
> +            testname = os.path.basename(test)
> +            print(f'# running {self.env.imgfmt} {testname}')
>   
>           res = self.do_run_test(test, mp)
>   

Reviewed-by: Thomas Huth <thuth@redhat.com>

I wonder whether we should flush stdout, too?

[PATCH 2/2] .gitlab-ci.d: export meson testlog.txt as an artifact

[Daniel P. Berrangé]

When running 'make check' we only get a summary of progress on the
console. Fortunately meson/ninja have saved the raw test output to a
logfile. Exposing this log will make it easier to debug failures that
happen in CI.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 .gitlab-ci.d/buildtest-template.yml | 12 ++++++++++--
 1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/.gitlab-ci.d/buildtest-template.yml b/.gitlab-ci.d/buildtest-template.yml
index 2c7980a4f6..dc6d67aacf 100644
--- a/.gitlab-ci.d/buildtest-template.yml
+++ b/.gitlab-ci.d/buildtest-template.yml
@@ -26,7 +26,7 @@
         make -j"$JOBS" $MAKE_CHECK_ARGS ;
       fi
 
-.native_test_job_template:
+.common_test_job_template:
   stage: test
   image: $CI_REGISTRY_IMAGE/qemu/$IMAGE:latest
   script:
@@ -37,8 +37,16 @@
     # Avoid recompiling by hiding ninja with NINJA=":"
     - make NINJA=":" $MAKE_CHECK_ARGS
 
+.native_test_job_template:
+  extends: .common_test_job_template
+  artifacts:
+    name: "$CI_JOB_NAME-$CI_COMMIT_REF_SLUG"
+    expire_in: 7 days
+    paths:
+      - build/meson-logs/testlog.txt
+
 .avocado_test_job_template:
-  extends: .native_test_job_template
+  extends: .common_test_job_template
   cache:
     key: "${CI_JOB_NAME}-cache"
     paths:
-- 
2.35.1

Re: [PATCH 2/2] .gitlab-ci.d: export meson testlog.txt as an artifact

[Thomas Huth]

On 09/05/2022 14.41, Daniel P. Berrangé wrote:
> When running 'make check' we only get a summary of progress on the
> console. Fortunately meson/ninja have saved the raw test output to a
> logfile. Exposing this log will make it easier to debug failures that
> happen in CI.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   .gitlab-ci.d/buildtest-template.yml | 12 ++++++++++--
>   1 file changed, 10 insertions(+), 2 deletions(-)
> 
> diff --git a/.gitlab-ci.d/buildtest-template.yml b/.gitlab-ci.d/buildtest-template.yml
> index 2c7980a4f6..dc6d67aacf 100644
> --- a/.gitlab-ci.d/buildtest-template.yml
> +++ b/.gitlab-ci.d/buildtest-template.yml
> @@ -26,7 +26,7 @@
>           make -j"$JOBS" $MAKE_CHECK_ARGS ;
>         fi
>   
> -.native_test_job_template:
> +.common_test_job_template:
>     stage: test
>     image: $CI_REGISTRY_IMAGE/qemu/$IMAGE:latest
>     script:
> @@ -37,8 +37,16 @@
>       # Avoid recompiling by hiding ninja with NINJA=":"
>       - make NINJA=":" $MAKE_CHECK_ARGS
>   
> +.native_test_job_template:
> +  extends: .common_test_job_template
> +  artifacts:
> +    name: "$CI_JOB_NAME-$CI_COMMIT_REF_SLUG"
> +    expire_in: 7 days
> +    paths:
> +      - build/meson-logs/testlog.txt
> +
>   .avocado_test_job_template:
> -  extends: .native_test_job_template
> +  extends: .common_test_job_template
>     cache:
>       key: "${CI_JOB_NAME}-cache"
>       paths:

Reviewed-by: Thomas Huth <thuth@redhat.com>

Re: [PATCH 2/2] .gitlab-ci.d: export meson testlog.txt as an artifact

[Philippe Mathieu-Daudé via]

On 9/5/22 14:41, Daniel P. Berrangé wrote:
> When running 'make check' we only get a summary of progress on the
> console. Fortunately meson/ninja have saved the raw test output to a
> logfile. Exposing this log will make it easier to debug failures that
> happen in CI.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   .gitlab-ci.d/buildtest-template.yml | 12 ++++++++++--
>   1 file changed, 10 insertions(+), 2 deletions(-)

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

Re: [PATCH 0/2] ci: improve debuggability of I/O tests

[Kevin Wolf]

Am 09.05.2022 um 14:41 hat Daniel P. Berrangé geschrieben:
> Currently with the TAP harness we see essentially no useful information
> about the I/O tests execution. To pick a random job:
> 
>   https://gitlab.com/qemu-project/qemu/-/jobs/2429330423
> 
> All that we get is this:
> 
>   184/204 qemu:block / qemu-iotests qcow2  OK  309.10s   116 subtests passed
> 
> The full details are in a testlog.txt file that isn't accessible. This
> series publishes that as an artifact. It further tweaks the TAP runner
> to print out when it is about to run a test, so we get a record of what
> was running, if the test harness gets terminated abnormally/prematurely

Thanks, applied to the block branch.

Kevin