[PATCH 0/8] testing/next: avocado logging, docs, gitlab

[PATCH 0/8] testing/next: avocado logging, docs, gitlab

[Alex Bennée]

Mostly this contains some fixes for the logging that went missing
since we bumped avocado up to 101. As well as tweaking the log
behaviour we also have a few gitlab tweaks from Daniel and some
updates to the documentation.

I've included Richards plugin fix so we don't break bisection although
it will likely go straight into the main tree by the time this becomes
a pull request.

Alex Bennée (4):
  tests/tcg: add mechanism to handle plugin arguments
  tests/avocado: move guest output to "avocado" namespace
  python/qemu: allow avocado to set logging name space
  docs: add some documentation on avocado logging

Ani Sinha (1):
  docs/devel: remind developers to run CI container pipeline when
    updating images

Daniel P. Berrangé (2):
  gitlab: explicit set artifacts publishing criteria
  gitlab: ensure coverage job also publishes meson log

Richard Henderson (1):
  accel/tcg: Fix append_mem_cb

 docs/devel/testing.rst                 | 31 +++++++++++++++++++
 accel/tcg/plugin-gen.c                 | 42 --------------------------
 .gitlab-ci.d/buildtest-template.yml    |  4 ++-
 .gitlab-ci.d/buildtest.yml             |  5 +++
 .gitlab-ci.d/crossbuild-template.yml   |  1 +
 .gitlab-ci.d/crossbuilds.yml           |  2 ++
 .gitlab-ci.d/custom-runners.yml        |  1 +
 .gitlab-ci.d/opensbi.yml               |  1 +
 python/qemu/machine/machine.py         | 42 ++++++++++++++------------
 tests/avocado/avocado_qemu/__init__.py |  7 +++--
 tests/tcg/Makefile.target              |  8 +++--
 11 files changed, 76 insertions(+), 68 deletions(-)

-- 
2.39.2

[PATCH 1/8] gitlab: explicit set artifacts publishing criteria

[Alex Bennée]

From: Daniel P. Berrangé <berrange@redhat.com>

If not set explicitly, gitlab assumes 'when: on_success" as the
publishing criteria for artifacts. This is reasonable if the
artifact is an output deliverable of the job. This is useless
if the artifact is a log file to be used for debugging job
failures.

This change makes the desired criteria explicit for every job
that publishes artifacts.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Message-Id: <20230503145535.91325-2-berrange@redhat.com>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 .gitlab-ci.d/buildtest-template.yml  | 4 +++-
 .gitlab-ci.d/buildtest.yml           | 2 ++
 .gitlab-ci.d/crossbuild-template.yml | 1 +
 .gitlab-ci.d/crossbuilds.yml         | 2 ++
 .gitlab-ci.d/custom-runners.yml      | 1 +
 .gitlab-ci.d/opensbi.yml             | 1 +
 6 files changed, 10 insertions(+), 1 deletion(-)

diff --git a/.gitlab-ci.d/buildtest-template.yml b/.gitlab-ci.d/buildtest-template.yml
index a6cfe9be97..d90bd6419f 100644
--- a/.gitlab-ci.d/buildtest-template.yml
+++ b/.gitlab-ci.d/buildtest-template.yml
@@ -29,6 +29,7 @@
 # rebuilding all the object files we skip in the artifacts
 .native_build_artifact_template:
   artifacts:
+    when: on_success
     expire_in: 2 days
     paths:
       - build
@@ -57,6 +58,7 @@
   extends: .common_test_job_template
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_REF_SLUG"
+    when: always
     expire_in: 7 days
     paths:
       - build/meson-logs/testlog.txt
@@ -72,7 +74,7 @@
     policy: pull-push
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_REF_SLUG"
-    when: on_failure
+    when: always
     expire_in: 7 days
     paths:
       - build/tests/results/latest/results.xml
diff --git a/.gitlab-ci.d/buildtest.yml b/.gitlab-ci.d/buildtest.yml
index bb3650a51c..0bb5cd56f9 100644
--- a/.gitlab-ci.d/buildtest.yml
+++ b/.gitlab-ci.d/buildtest.yml
@@ -462,6 +462,7 @@ gcov:
   coverage: /^\s*lines:\s*\d+.\d+\%/
   artifacts:
     name: ${CI_JOB_NAME}-${CI_COMMIT_REF_NAME}-${CI_COMMIT_SHA}
+    when: on_success
     expire_in: 2 days
     reports:
       coverage_report:
@@ -587,6 +588,7 @@ pages:
     - make -C build install DESTDIR=$(pwd)/temp-install
     - mv temp-install/usr/local/share/doc/qemu/* public/
   artifacts:
+    when: on_success
     paths:
       - public
   variables:
diff --git a/.gitlab-ci.d/crossbuild-template.yml b/.gitlab-ci.d/crossbuild-template.yml
index 4f93b9e4e5..a7e34e0145 100644
--- a/.gitlab-ci.d/crossbuild-template.yml
+++ b/.gitlab-ci.d/crossbuild-template.yml
@@ -55,6 +55,7 @@
 .cross_test_artifacts:
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_REF_SLUG"
+    when: always
     expire_in: 7 days
     paths:
       - build/meson-logs/testlog.txt
diff --git a/.gitlab-ci.d/crossbuilds.yml b/.gitlab-ci.d/crossbuilds.yml
index 61b8ac86ee..ee4c1b74d9 100644
--- a/.gitlab-ci.d/crossbuilds.yml
+++ b/.gitlab-ci.d/crossbuilds.yml
@@ -161,6 +161,7 @@ cross-win32-system:
     CROSS_SKIP_TARGETS: alpha-softmmu avr-softmmu hppa-softmmu m68k-softmmu
                         microblazeel-softmmu mips64el-softmmu nios2-softmmu
   artifacts:
+    when: on_success
     paths:
       - build/qemu-setup*.exe
 
@@ -176,6 +177,7 @@ cross-win64-system:
                         or1k-softmmu rx-softmmu sh4eb-softmmu sparc64-softmmu
                         tricore-softmmu xtensaeb-softmmu
   artifacts:
+    when: on_success
     paths:
       - build/qemu-setup*.exe
 
diff --git a/.gitlab-ci.d/custom-runners.yml b/.gitlab-ci.d/custom-runners.yml
index 34a1e6f327..a0aef96a07 100644
--- a/.gitlab-ci.d/custom-runners.yml
+++ b/.gitlab-ci.d/custom-runners.yml
@@ -20,6 +20,7 @@ variables:
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_REF_SLUG"
     expire_in: 7 days
+    when: always
     paths:
       - build/meson-logs/testlog.txt
     reports:
diff --git a/.gitlab-ci.d/opensbi.yml b/.gitlab-ci.d/opensbi.yml
index 9a651465d8..867e34c19f 100644
--- a/.gitlab-ci.d/opensbi.yml
+++ b/.gitlab-ci.d/opensbi.yml
@@ -65,6 +65,7 @@ build-opensbi:
   stage: build
   needs: ['docker-opensbi']
   artifacts:
+    when: on_success
     paths: # 'artifacts.zip' will contains the following files:
       - pc-bios/opensbi-riscv32-generic-fw_dynamic.bin
       - pc-bios/opensbi-riscv64-generic-fw_dynamic.bin
-- 
2.39.2

[PATCH 2/8] gitlab: ensure coverage job also publishes meson log

[Alex Bennée]

From: Daniel P. Berrangé <berrange@redhat.com>

The coverage job wants to publish a coverage report on success, but the
tests might fail and in that case we need the meson logs for debugging.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Message-Id: <20230503145535.91325-3-berrange@redhat.com>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 .gitlab-ci.d/buildtest.yml | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/.gitlab-ci.d/buildtest.yml b/.gitlab-ci.d/buildtest.yml
index 0bb5cd56f9..b6390e3562 100644
--- a/.gitlab-ci.d/buildtest.yml
+++ b/.gitlab-ci.d/buildtest.yml
@@ -462,9 +462,12 @@ gcov:
   coverage: /^\s*lines:\s*\d+.\d+\%/
   artifacts:
     name: ${CI_JOB_NAME}-${CI_COMMIT_REF_NAME}-${CI_COMMIT_SHA}
-    when: on_success
+    when: always
     expire_in: 2 days
+    paths:
+      - build/meson-logs/testlog.txt
     reports:
+      junit: build/meson-logs/testlog.junit.xml
       coverage_report:
         coverage_format: cobertura
         path: build/coverage.xml
-- 
2.39.2

[PATCH 3/8] docs/devel: remind developers to run CI container pipeline when updating images

[Alex Bennée]

From: Ani Sinha <anisinha@redhat.com>

When new dependencies and packages are added to containers, its important to
run CI container generation pipelines on gitlab to make sure that there are no
obvious conflicts between packages that are being added and those that are
already present. Running CI container pipelines will make sure that there are
no such breakages before we commit the change updating the containers. Add a
line in the documentation reminding developers to run the pipeline before
submitting the change. It will also ease the life of the maintainers.

Signed-off-by: Ani Sinha <anisinha@redhat.com>
Reviewed-by: Daniel P. Berrangé <berrange@redhat.com>
Message-Id: <20230506072012.10350-1-anisinha@redhat.com>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 docs/devel/testing.rst | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/docs/devel/testing.rst b/docs/devel/testing.rst
index 203facb417..8f18052ba7 100644
--- a/docs/devel/testing.rst
+++ b/docs/devel/testing.rst
@@ -485,6 +485,12 @@ first to contribute the mapping to the ``libvirt-ci`` project:
    `CI <https://www.qemu.org/docs/master/devel/ci.html>`__ documentation
    page on how to trigger gitlab CI pipelines on your change.
 
+ * Please also trigger gitlab container generation pipelines on your change
+   for as many OS distros as practical to make sure that there are no
+   obvious breakages when adding the new pre-requisite. Please see
+   `CI <https://www.qemu.org/docs/master/devel/ci.html>`__ documentation
+   page on how to trigger gitlab CI pipelines on your change.
+
 For enterprise distros that default to old, end-of-life versions of the
 Python runtime, QEMU uses a separate set of mappings that work with more
 recent versions.  These can be found in ``tests/lcitool/mappings.yml``.
-- 
2.39.2

[PATCH 4/8] accel/tcg: Fix append_mem_cb

[Alex Bennée]

From: Richard Henderson <richard.henderson@linaro.org>

In fcdab382c8b9 we removed a tcg_gen_extu_tl_i64 from gen_empty_mem_cb,
and failed to adjust the associated copy, leading to a failed assert.

Fixes: fcdab382c8b9 ("accel/tcg: Widen plugin_gen_empty_mem_callback to i64")
Signed-off-by: Richard Henderson <richard.henderson@linaro.org>
Message-Id: <20230518145813.2940745-1-richard.henderson@linaro.org>
Reviewed-by: Alex Bennée <alex.bennee@linaro.org>
Tested-by: Alex Bennée <alex.bennee@linaro.org>
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 accel/tcg/plugin-gen.c | 42 ------------------------------------------
 1 file changed, 42 deletions(-)

diff --git a/accel/tcg/plugin-gen.c b/accel/tcg/plugin-gen.c
index 34be1b940c..5b73a39ce5 100644
--- a/accel/tcg/plugin-gen.c
+++ b/accel/tcg/plugin-gen.c
@@ -254,33 +254,6 @@ static TCGOp *copy_op(TCGOp **begin_op, TCGOp *op, TCGOpcode opc)
     return op;
 }
 
-static TCGOp *copy_extu_i32_i64(TCGOp **begin_op, TCGOp *op)
-{
-    if (TCG_TARGET_REG_BITS == 32) {
-        /* mov_i32 */
-        op = copy_op(begin_op, op, INDEX_op_mov_i32);
-        /* mov_i32 w/ $0 */
-        op = copy_op(begin_op, op, INDEX_op_mov_i32);
-    } else {
-        /* extu_i32_i64 */
-        op = copy_op(begin_op, op, INDEX_op_extu_i32_i64);
-    }
-    return op;
-}
-
-static TCGOp *copy_mov_i64(TCGOp **begin_op, TCGOp *op)
-{
-    if (TCG_TARGET_REG_BITS == 32) {
-        /* 2x mov_i32 */
-        op = copy_op(begin_op, op, INDEX_op_mov_i32);
-        op = copy_op(begin_op, op, INDEX_op_mov_i32);
-    } else {
-        /* mov_i64 */
-        op = copy_op(begin_op, op, INDEX_op_mov_i64);
-    }
-    return op;
-}
-
 static TCGOp *copy_const_ptr(TCGOp **begin_op, TCGOp *op, void *ptr)
 {
     if (UINTPTR_MAX == UINT32_MAX) {
@@ -295,18 +268,6 @@ static TCGOp *copy_const_ptr(TCGOp **begin_op, TCGOp *op, void *ptr)
     return op;
 }
 
-static TCGOp *copy_extu_tl_i64(TCGOp **begin_op, TCGOp *op)
-{
-    if (TARGET_LONG_BITS == 32) {
-        /* extu_i32_i64 */
-        op = copy_extu_i32_i64(begin_op, op);
-    } else {
-        /* mov_i64 */
-        op = copy_mov_i64(begin_op, op);
-    }
-    return op;
-}
-
 static TCGOp *copy_ld_i64(TCGOp **begin_op, TCGOp *op)
 {
     if (TCG_TARGET_REG_BITS == 32) {
@@ -451,9 +412,6 @@ static TCGOp *append_mem_cb(const struct qemu_plugin_dyn_cb *cb,
         tcg_debug_assert(begin_op && begin_op->opc == INDEX_op_ld_i32);
     }
 
-    /* extu_tl_i64 */
-    op = copy_extu_tl_i64(&begin_op, op);
-
     if (type == PLUGIN_GEN_CB_MEM) {
         /* call */
         op = copy_call(&begin_op, op, HELPER(plugin_vcpu_mem_cb),
-- 
2.39.2

[PATCH 5/8] tests/tcg: add mechanism to handle plugin arguments

[Alex Bennée]

We recently missed a regression that should have been picked up by
check-tcg. This was because the libmem plugin is effectively a NOP if
the user doesn't specify the type to use.

Rather than changing the default behaviour add an additional expansion
so we can take this into account in future.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Richard Henderson <richard.henderson@linaro.org>
---
 tests/tcg/Makefile.target | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/tests/tcg/Makefile.target b/tests/tcg/Makefile.target
index 72876cc84e..2462c26000 100644
--- a/tests/tcg/Makefile.target
+++ b/tests/tcg/Makefile.target
@@ -169,13 +169,17 @@ extract-plugin = $(wordlist 2, 2, $(subst -with-, ,$1))
 
 RUN_TESTS+=$(EXTRA_RUNS)
 
+# Some plugins need additional arguments above the default to fully
+# exercise things. We can define them on a per-test basis here.
+run-plugin-%-with-libmem.so: PLUGIN_ARGS=$(COMMA)inline=true$(COMMA)callback=true
+
 ifeq ($(filter %-softmmu, $(TARGET)),)
 run-%: %
 	$(call run-test, $<, $(QEMU) $(QEMU_OPTS) $<)
 
 run-plugin-%:
 	$(call run-test, $@, $(QEMU) $(QEMU_OPTS) \
-		-plugin $(PLUGIN_LIB)/$(call extract-plugin,$@) \
+		-plugin $(PLUGIN_LIB)/$(call extract-plugin,$@)$(PLUGIN_ARGS) \
 		-d plugin -D $*.pout \
 		 $(call strip-plugin,$<))
 else
@@ -189,7 +193,7 @@ run-plugin-%:
 	$(call run-test, $@, \
 	  $(QEMU) -monitor none -display none \
 		  -chardev file$(COMMA)path=$@.out$(COMMA)id=output \
-	   	  -plugin $(PLUGIN_LIB)/$(call extract-plugin,$@) \
+	   	  -plugin $(PLUGIN_LIB)/$(call extract-plugin,$@)$(PLUGIN_ARGS) \
 	    	  -d plugin -D $*.pout \
 		  $(QEMU_OPTS) $(call strip-plugin,$<))
 endif
-- 
2.39.2

[PATCH 6/8] tests/avocado: move guest output to "avocado" namespace

[Alex Bennée]

It has been noted that console logs have disappeared since the update
to the latest avocado. This seems to fix it.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 tests/avocado/avocado_qemu/__init__.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/tests/avocado/avocado_qemu/__init__.py b/tests/avocado/avocado_qemu/__init__.py
index 33090903f1..b19f797b7b 100644
--- a/tests/avocado/avocado_qemu/__init__.py
+++ b/tests/avocado/avocado_qemu/__init__.py
@@ -138,7 +138,7 @@ def _console_interaction(test, success_message, failure_message,
     if vm is None:
         vm = test.vm
     console = vm.console_socket.makefile(mode='rb', encoding='utf-8')
-    console_logger = logging.getLogger('console')
+    console_logger = logging.getLogger('avocado.guest.console')
     while True:
         if send_string:
             vm.console_socket.sendall(send_string.encode())
@@ -407,7 +407,7 @@ class LinuxSSHMixIn:
     """Contains utility methods for interacting with a guest via SSH."""
 
     def ssh_connect(self, username, credential, credential_is_key=True):
-        self.ssh_logger = logging.getLogger('ssh')
+        self.ssh_logger = logging.getLogger('avocado.guest.ssh')
         res = self.vm.command('human-monitor-command',
                               command_line='info usernet')
         port = get_info_usernet_hostfwd_port(res)
-- 
2.39.2

[PATCH 7/8] python/qemu: allow avocado to set logging name space

[Alex Bennée]

Since the update to the latest version Avocado only automatically
collects logging under the avocado name space. Tweak the QEMUMachine
class to allow avocado to bring logging under its name space. This
also allows useful tricks like:

  ./avocado --show avocado.qemu.machine run path/to/test

if you want to quickly get the machine invocation out of a test
without searching deeply through the logs.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 python/qemu/machine/machine.py         | 42 ++++++++++++++------------
 tests/avocado/avocado_qemu/__init__.py |  3 +-
 2 files changed, 24 insertions(+), 21 deletions(-)

diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
index e57c254484..402b9a0df9 100644
--- a/python/qemu/machine/machine.py
+++ b/python/qemu/machine/machine.py
@@ -49,10 +49,6 @@
 
 from . import console_socket
 
-
-LOG = logging.getLogger(__name__)
-
-
 class QEMUMachineError(Exception):
     """
     Exception called when an error in QEMUMachine happens.
@@ -131,6 +127,7 @@ def __init__(self,
                  drain_console: bool = False,
                  console_log: Optional[str] = None,
                  log_dir: Optional[str] = None,
+                 log_namespace: Optional[str] = None,
                  qmp_timer: Optional[float] = 30):
         '''
         Initialize a QEMUMachine
@@ -164,6 +161,11 @@ def __init__(self,
         self._sock_dir = sock_dir
         self._log_dir = log_dir
 
+        if log_namespace:
+            self.log = logging.getLogger(log_namespace)
+        else:
+            self.log = logging.getLogger(__name__)
+
         self._monitor_address = monitor_address
 
         self._console_log_path = console_log
@@ -382,11 +384,11 @@ def _post_shutdown(self) -> None:
         Called to cleanup the VM instance after the process has exited.
         May also be called after a failed launch.
         """
-        LOG.debug("Cleaning up after VM process")
+        self.log.debug("Cleaning up after VM process")
         try:
             self._close_qmp_connection()
         except Exception as err:  # pylint: disable=broad-except
-            LOG.warning(
+            self.log.warning(
                 "Exception closing QMP connection: %s",
                 str(err) if str(err) else type(err).__name__
             )
@@ -414,7 +416,7 @@ def _post_shutdown(self) -> None:
                 command = ' '.join(self._qemu_full_args)
             else:
                 command = ''
-            LOG.warning(msg, -int(exitcode), command)
+            self.log.warning(msg, -int(exitcode), command)
 
         self._quit_issued = False
         self._user_killed = False
@@ -458,7 +460,7 @@ def _launch(self) -> None:
         Launch the VM and establish a QMP connection
         """
         self._pre_launch()
-        LOG.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
+        self.log.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
 
         # Cleaning up of this subprocess is guaranteed by _do_shutdown.
         # pylint: disable=consider-using-with
@@ -507,7 +509,7 @@ def _early_cleanup(self) -> None:
         # for QEMU to exit, while QEMU is waiting for the socket to
         # become writable.
         if self._console_socket is not None:
-            LOG.debug("Closing console socket")
+            self.log.debug("Closing console socket")
             self._console_socket.close()
             self._console_socket = None
 
@@ -518,7 +520,7 @@ def _hard_shutdown(self) -> None:
         :raise subprocess.Timeout: When timeout is exceeds 60 seconds
             waiting for the QEMU process to terminate.
         """
-        LOG.debug("Performing hard shutdown")
+        self.log.debug("Performing hard shutdown")
         self._early_cleanup()
         self._subp.kill()
         self._subp.wait(timeout=60)
@@ -535,17 +537,17 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
         :raise subprocess.TimeoutExpired: When timeout is exceeded waiting for
             the QEMU process to terminate.
         """
-        LOG.debug("Attempting graceful termination")
+        self.log.debug("Attempting graceful termination")
 
         self._early_cleanup()
 
         if self._quit_issued:
-            LOG.debug(
+            self.log.debug(
                 "Anticipating QEMU termination due to prior 'quit' command, "
                 "or explicit call to wait()"
             )
         else:
-            LOG.debug("Politely asking QEMU to terminate")
+            self.log.debug("Politely asking QEMU to terminate")
 
         if self._qmp_connection:
             try:
@@ -557,14 +559,14 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
                 # Regardless, we want to quiesce the connection.
                 self._close_qmp_connection()
         elif not self._quit_issued:
-            LOG.debug(
+            self.log.debug(
                 "Not anticipating QEMU quit and no QMP connection present, "
                 "issuing SIGTERM"
             )
             self._subp.terminate()
 
         # May raise subprocess.TimeoutExpired
-        LOG.debug(
+        self.log.debug(
             "Waiting (timeout=%s) for QEMU process (pid=%s) to terminate",
             timeout, self._subp.pid
         )
@@ -586,9 +588,9 @@ def _do_shutdown(self, timeout: Optional[int]) -> None:
             self._soft_shutdown(timeout)
         except Exception as exc:
             if isinstance(exc, subprocess.TimeoutExpired):
-                LOG.debug("Timed out waiting for QEMU process to exit")
-            LOG.debug("Graceful shutdown failed", exc_info=True)
-            LOG.debug("Falling back to hard shutdown")
+                self.log.debug("Timed out waiting for QEMU process to exit")
+            self.log.debug("Graceful shutdown failed", exc_info=True)
+            self.log.debug("Falling back to hard shutdown")
             self._hard_shutdown()
             raise AbnormalShutdown("Could not perform graceful shutdown") \
                 from exc
@@ -611,9 +613,9 @@ def shutdown(self,
         if not self._launched:
             return
 
-        LOG.debug("Shutting down VM appliance; timeout=%s", timeout)
+        self.log.debug("Shutting down VM appliance; timeout=%s", timeout)
         if hard:
-            LOG.debug("Caller requests immediate termination of QEMU process.")
+            self.log.debug("Caller requests immediate termination of QEMU process.")
 
         try:
             if hard:
diff --git a/tests/avocado/avocado_qemu/__init__.py b/tests/avocado/avocado_qemu/__init__.py
index b19f797b7b..d925573299 100644
--- a/tests/avocado/avocado_qemu/__init__.py
+++ b/tests/avocado/avocado_qemu/__init__.py
@@ -322,7 +322,8 @@ def require_multiprocess(self):
     def _new_vm(self, name, *args):
         self._sd = tempfile.TemporaryDirectory(prefix="qemu_")
         vm = QEMUMachine(self.qemu_bin, base_temp_dir=self.workdir,
-                         sock_dir=self._sd.name, log_dir=self.logdir)
+                         sock_dir=self._sd.name, log_dir=self.logdir,
+                         log_namespace="avocado.qemu.machine")
         self.log.debug('QEMUMachine "%s" created', name)
         self.log.debug('QEMUMachine "%s" temp_dir: %s', name, vm.temp_dir)
         self.log.debug('QEMUMachine "%s" log_dir: %s', name, vm.log_dir)
-- 
2.39.2

[PATCH 8/8] docs: add some documentation on avocado logging

[Alex Bennée]

While we have fixed the logging to go under the avocado name space we
might as well mention the useful "--show" option and the streams you
can use it on.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 docs/devel/testing.rst | 25 +++++++++++++++++++++++++
 1 file changed, 25 insertions(+)

diff --git a/docs/devel/testing.rst b/docs/devel/testing.rst
index 8f18052ba7..77402a0daf 100644
--- a/docs/devel/testing.rst
+++ b/docs/devel/testing.rst
@@ -983,6 +983,31 @@ of Avocado or ``make check-avocado``, and can also be queried using:
 
   tests/venv/bin/avocado list tests/avocado
 
+Logs
+^^^^
+
+Avocado collects anything logged under the 'avocado.*' name space in
+the log files for a given run. You can also use the ``--show`` option
+to dump selected logging streams directly to stdout:
+
+  .. code::
+
+   tests/venv/bin/avocado --show avocado.qemu.machine run tests/avocado/$TESTFILE:$TESTCLASS.$TESTNAME
+
+There are a number of useful streams you can select.
+
+.. list-table:: Avocado Logging Streams
+  :header-rows: 1
+
+  * - Stream Name
+    - Contents
+  * - avocado.qemu.machine
+    - VM lifecycle including the launch command
+  * - avocado.guest.console
+    - Serial console interactions
+  * - avocado.guest.ssh
+    - ssh interactions
+
 Manual Installation
 ~~~~~~~~~~~~~~~~~~~
 
-- 
2.39.2

Re: [PATCH 7/8] python/qemu: allow avocado to set logging name space

[John Snow]

On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.bennee@linaro.org> wrote:
>
> Since the update to the latest version Avocado only automatically
> collects logging under the avocado name space. Tweak the QEMUMachine
> class to allow avocado to bring logging under its name space. This
> also allows useful tricks like:
>
>   ./avocado --show avocado.qemu.machine run path/to/test
>
> if you want to quickly get the machine invocation out of a test
> without searching deeply through the logs.
>

Huh. That's kind of weird though, right? Each Python module is
intended to log to its own namespace by design; it feels like Avocado
really ought to have configuration options that allows it to collect
logging from other namespaces. I'm not against this patch, but if for
instance I wind up splitting qemu.machine out as a separate module
someday (like I did to qemu.qmp), then it feels weird to add options
specifically for fudging the logging hierarchy.

Also, what about the QMP logging? I don't suppose this will trickle
down to that level either.

Worried this is kind of incomplete.

--js

> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  python/qemu/machine/machine.py         | 42 ++++++++++++++------------
>  tests/avocado/avocado_qemu/__init__.py |  3 +-
>  2 files changed, 24 insertions(+), 21 deletions(-)
>
> diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
> index e57c254484..402b9a0df9 100644
> --- a/python/qemu/machine/machine.py
> +++ b/python/qemu/machine/machine.py
> @@ -49,10 +49,6 @@
>
>  from . import console_socket
>
> -
> -LOG = logging.getLogger(__name__)
> -
> -
>  class QEMUMachineError(Exception):
>      """
>      Exception called when an error in QEMUMachine happens.
> @@ -131,6 +127,7 @@ def __init__(self,
>                   drain_console: bool = False,
>                   console_log: Optional[str] = None,
>                   log_dir: Optional[str] = None,
> +                 log_namespace: Optional[str] = None,
>                   qmp_timer: Optional[float] = 30):
>          '''
>          Initialize a QEMUMachine
> @@ -164,6 +161,11 @@ def __init__(self,
>          self._sock_dir = sock_dir
>          self._log_dir = log_dir
>
> +        if log_namespace:
> +            self.log = logging.getLogger(log_namespace)
> +        else:
> +            self.log = logging.getLogger(__name__)
> +
>          self._monitor_address = monitor_address
>
>          self._console_log_path = console_log
> @@ -382,11 +384,11 @@ def _post_shutdown(self) -> None:
>          Called to cleanup the VM instance after the process has exited.
>          May also be called after a failed launch.
>          """
> -        LOG.debug("Cleaning up after VM process")
> +        self.log.debug("Cleaning up after VM process")
>          try:
>              self._close_qmp_connection()
>          except Exception as err:  # pylint: disable=broad-except
> -            LOG.warning(
> +            self.log.warning(
>                  "Exception closing QMP connection: %s",
>                  str(err) if str(err) else type(err).__name__
>              )
> @@ -414,7 +416,7 @@ def _post_shutdown(self) -> None:
>                  command = ' '.join(self._qemu_full_args)
>              else:
>                  command = ''
> -            LOG.warning(msg, -int(exitcode), command)
> +            self.log.warning(msg, -int(exitcode), command)
>
>          self._quit_issued = False
>          self._user_killed = False
> @@ -458,7 +460,7 @@ def _launch(self) -> None:
>          Launch the VM and establish a QMP connection
>          """
>          self._pre_launch()
> -        LOG.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
> +        self.log.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
>
>          # Cleaning up of this subprocess is guaranteed by _do_shutdown.
>          # pylint: disable=consider-using-with
> @@ -507,7 +509,7 @@ def _early_cleanup(self) -> None:
>          # for QEMU to exit, while QEMU is waiting for the socket to
>          # become writable.
>          if self._console_socket is not None:
> -            LOG.debug("Closing console socket")
> +            self.log.debug("Closing console socket")
>              self._console_socket.close()
>              self._console_socket = None
>
> @@ -518,7 +520,7 @@ def _hard_shutdown(self) -> None:
>          :raise subprocess.Timeout: When timeout is exceeds 60 seconds
>              waiting for the QEMU process to terminate.
>          """
> -        LOG.debug("Performing hard shutdown")
> +        self.log.debug("Performing hard shutdown")
>          self._early_cleanup()
>          self._subp.kill()
>          self._subp.wait(timeout=60)
> @@ -535,17 +537,17 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
>          :raise subprocess.TimeoutExpired: When timeout is exceeded waiting for
>              the QEMU process to terminate.
>          """
> -        LOG.debug("Attempting graceful termination")
> +        self.log.debug("Attempting graceful termination")
>
>          self._early_cleanup()
>
>          if self._quit_issued:
> -            LOG.debug(
> +            self.log.debug(
>                  "Anticipating QEMU termination due to prior 'quit' command, "
>                  "or explicit call to wait()"
>              )
>          else:
> -            LOG.debug("Politely asking QEMU to terminate")
> +            self.log.debug("Politely asking QEMU to terminate")
>
>          if self._qmp_connection:
>              try:
> @@ -557,14 +559,14 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
>                  # Regardless, we want to quiesce the connection.
>                  self._close_qmp_connection()
>          elif not self._quit_issued:
> -            LOG.debug(
> +            self.log.debug(
>                  "Not anticipating QEMU quit and no QMP connection present, "
>                  "issuing SIGTERM"
>              )
>              self._subp.terminate()
>
>          # May raise subprocess.TimeoutExpired
> -        LOG.debug(
> +        self.log.debug(
>              "Waiting (timeout=%s) for QEMU process (pid=%s) to terminate",
>              timeout, self._subp.pid
>          )
> @@ -586,9 +588,9 @@ def _do_shutdown(self, timeout: Optional[int]) -> None:
>              self._soft_shutdown(timeout)
>          except Exception as exc:
>              if isinstance(exc, subprocess.TimeoutExpired):
> -                LOG.debug("Timed out waiting for QEMU process to exit")
> -            LOG.debug("Graceful shutdown failed", exc_info=True)
> -            LOG.debug("Falling back to hard shutdown")
> +                self.log.debug("Timed out waiting for QEMU process to exit")
> +            self.log.debug("Graceful shutdown failed", exc_info=True)
> +            self.log.debug("Falling back to hard shutdown")
>              self._hard_shutdown()
>              raise AbnormalShutdown("Could not perform graceful shutdown") \
>                  from exc
> @@ -611,9 +613,9 @@ def shutdown(self,
>          if not self._launched:
>              return
>
> -        LOG.debug("Shutting down VM appliance; timeout=%s", timeout)
> +        self.log.debug("Shutting down VM appliance; timeout=%s", timeout)
>          if hard:
> -            LOG.debug("Caller requests immediate termination of QEMU process.")
> +            self.log.debug("Caller requests immediate termination of QEMU process.")
>
>          try:
>              if hard:
> diff --git a/tests/avocado/avocado_qemu/__init__.py b/tests/avocado/avocado_qemu/__init__.py
> index b19f797b7b..d925573299 100644
> --- a/tests/avocado/avocado_qemu/__init__.py
> +++ b/tests/avocado/avocado_qemu/__init__.py
> @@ -322,7 +322,8 @@ def require_multiprocess(self):
>      def _new_vm(self, name, *args):
>          self._sd = tempfile.TemporaryDirectory(prefix="qemu_")
>          vm = QEMUMachine(self.qemu_bin, base_temp_dir=self.workdir,
> -                         sock_dir=self._sd.name, log_dir=self.logdir)
> +                         sock_dir=self._sd.name, log_dir=self.logdir,
> +                         log_namespace="avocado.qemu.machine")
>          self.log.debug('QEMUMachine "%s" created', name)
>          self.log.debug('QEMUMachine "%s" temp_dir: %s', name, vm.temp_dir)
>          self.log.debug('QEMUMachine "%s" log_dir: %s', name, vm.log_dir)
> --
> 2.39.2
>

Re: [PATCH 7/8] python/qemu: allow avocado to set logging name space

[Alex Bennée]

John Snow <jsnow@redhat.com> writes:

> On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.bennee@linaro.org> wrote:
>>
>> Since the update to the latest version Avocado only automatically
>> collects logging under the avocado name space. Tweak the QEMUMachine
>> class to allow avocado to bring logging under its name space. This
>> also allows useful tricks like:
>>
>>   ./avocado --show avocado.qemu.machine run path/to/test
>>
>> if you want to quickly get the machine invocation out of a test
>> without searching deeply through the logs.
>>
>
> Huh. That's kind of weird though, right? Each Python module is
> intended to log to its own namespace by design; it feels like Avocado
> really ought to have configuration options that allows it to collect
> logging from other namespaces. I'm not against this patch, but if for
> instance I wind up splitting qemu.machine out as a separate module
> someday (like I did to qemu.qmp), then it feels weird to add options
> specifically for fudging the logging hierarchy.

According to the docs it does but I couldn't get it to work so this is a
sticking plaster over that. If it gets fixed in later avocado's it is
easy enough to remove.

> Also, what about the QMP logging? I don't suppose this will trickle
> down to that level either.

I can certainly add that - but it would need a similar hook.

>
> Worried this is kind of incomplete.
>
> --js
>
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> ---
>>  python/qemu/machine/machine.py         | 42 ++++++++++++++------------
>>  tests/avocado/avocado_qemu/__init__.py |  3 +-
>>  2 files changed, 24 insertions(+), 21 deletions(-)
>>
>> diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
>> index e57c254484..402b9a0df9 100644
>> --- a/python/qemu/machine/machine.py
>> +++ b/python/qemu/machine/machine.py
>> @@ -49,10 +49,6 @@
>>
>>  from . import console_socket
>>
>> -
>> -LOG = logging.getLogger(__name__)
>> -
>> -
>>  class QEMUMachineError(Exception):
>>      """
>>      Exception called when an error in QEMUMachine happens.
>> @@ -131,6 +127,7 @@ def __init__(self,
>>                   drain_console: bool = False,
>>                   console_log: Optional[str] = None,
>>                   log_dir: Optional[str] = None,
>> +                 log_namespace: Optional[str] = None,
>>                   qmp_timer: Optional[float] = 30):
>>          '''
>>          Initialize a QEMUMachine
>> @@ -164,6 +161,11 @@ def __init__(self,
>>          self._sock_dir = sock_dir
>>          self._log_dir = log_dir
>>
>> +        if log_namespace:
>> +            self.log = logging.getLogger(log_namespace)
>> +        else:
>> +            self.log = logging.getLogger(__name__)
>> +
>>          self._monitor_address = monitor_address
>>
>>          self._console_log_path = console_log
>> @@ -382,11 +384,11 @@ def _post_shutdown(self) -> None:
>>          Called to cleanup the VM instance after the process has exited.
>>          May also be called after a failed launch.
>>          """
>> -        LOG.debug("Cleaning up after VM process")
>> +        self.log.debug("Cleaning up after VM process")
>>          try:
>>              self._close_qmp_connection()
>>          except Exception as err:  # pylint: disable=broad-except
>> -            LOG.warning(
>> +            self.log.warning(
>>                  "Exception closing QMP connection: %s",
>>                  str(err) if str(err) else type(err).__name__
>>              )
>> @@ -414,7 +416,7 @@ def _post_shutdown(self) -> None:
>>                  command = ' '.join(self._qemu_full_args)
>>              else:
>>                  command = ''
>> -            LOG.warning(msg, -int(exitcode), command)
>> +            self.log.warning(msg, -int(exitcode), command)
>>
>>          self._quit_issued = False
>>          self._user_killed = False
>> @@ -458,7 +460,7 @@ def _launch(self) -> None:
>>          Launch the VM and establish a QMP connection
>>          """
>>          self._pre_launch()
>> -        LOG.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
>> +        self.log.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
>>
>>          # Cleaning up of this subprocess is guaranteed by _do_shutdown.
>>          # pylint: disable=consider-using-with
>> @@ -507,7 +509,7 @@ def _early_cleanup(self) -> None:
>>          # for QEMU to exit, while QEMU is waiting for the socket to
>>          # become writable.
>>          if self._console_socket is not None:
>> -            LOG.debug("Closing console socket")
>> +            self.log.debug("Closing console socket")
>>              self._console_socket.close()
>>              self._console_socket = None
>>
>> @@ -518,7 +520,7 @@ def _hard_shutdown(self) -> None:
>>          :raise subprocess.Timeout: When timeout is exceeds 60 seconds
>>              waiting for the QEMU process to terminate.
>>          """
>> -        LOG.debug("Performing hard shutdown")
>> +        self.log.debug("Performing hard shutdown")
>>          self._early_cleanup()
>>          self._subp.kill()
>>          self._subp.wait(timeout=60)
>> @@ -535,17 +537,17 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
>>          :raise subprocess.TimeoutExpired: When timeout is exceeded waiting for
>>              the QEMU process to terminate.
>>          """
>> -        LOG.debug("Attempting graceful termination")
>> +        self.log.debug("Attempting graceful termination")
>>
>>          self._early_cleanup()
>>
>>          if self._quit_issued:
>> -            LOG.debug(
>> +            self.log.debug(
>>                  "Anticipating QEMU termination due to prior 'quit' command, "
>>                  "or explicit call to wait()"
>>              )
>>          else:
>> -            LOG.debug("Politely asking QEMU to terminate")
>> +            self.log.debug("Politely asking QEMU to terminate")
>>
>>          if self._qmp_connection:
>>              try:
>> @@ -557,14 +559,14 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
>>                  # Regardless, we want to quiesce the connection.
>>                  self._close_qmp_connection()
>>          elif not self._quit_issued:
>> -            LOG.debug(
>> +            self.log.debug(
>>                  "Not anticipating QEMU quit and no QMP connection present, "
>>                  "issuing SIGTERM"
>>              )
>>              self._subp.terminate()
>>
>>          # May raise subprocess.TimeoutExpired
>> -        LOG.debug(
>> +        self.log.debug(
>>              "Waiting (timeout=%s) for QEMU process (pid=%s) to terminate",
>>              timeout, self._subp.pid
>>          )
>> @@ -586,9 +588,9 @@ def _do_shutdown(self, timeout: Optional[int]) -> None:
>>              self._soft_shutdown(timeout)
>>          except Exception as exc:
>>              if isinstance(exc, subprocess.TimeoutExpired):
>> -                LOG.debug("Timed out waiting for QEMU process to exit")
>> -            LOG.debug("Graceful shutdown failed", exc_info=True)
>> -            LOG.debug("Falling back to hard shutdown")
>> +                self.log.debug("Timed out waiting for QEMU process to exit")
>> +            self.log.debug("Graceful shutdown failed", exc_info=True)
>> +            self.log.debug("Falling back to hard shutdown")
>>              self._hard_shutdown()
>>              raise AbnormalShutdown("Could not perform graceful shutdown") \
>>                  from exc
>> @@ -611,9 +613,9 @@ def shutdown(self,
>>          if not self._launched:
>>              return
>>
>> -        LOG.debug("Shutting down VM appliance; timeout=%s", timeout)
>> +        self.log.debug("Shutting down VM appliance; timeout=%s", timeout)
>>          if hard:
>> -            LOG.debug("Caller requests immediate termination of QEMU process.")
>> +            self.log.debug("Caller requests immediate termination of QEMU process.")
>>
>>          try:
>>              if hard:
>> diff --git a/tests/avocado/avocado_qemu/__init__.py b/tests/avocado/avocado_qemu/__init__.py
>> index b19f797b7b..d925573299 100644
>> --- a/tests/avocado/avocado_qemu/__init__.py
>> +++ b/tests/avocado/avocado_qemu/__init__.py
>> @@ -322,7 +322,8 @@ def require_multiprocess(self):
>>      def _new_vm(self, name, *args):
>>          self._sd = tempfile.TemporaryDirectory(prefix="qemu_")
>>          vm = QEMUMachine(self.qemu_bin, base_temp_dir=self.workdir,
>> -                         sock_dir=self._sd.name, log_dir=self.logdir)
>> +                         sock_dir=self._sd.name, log_dir=self.logdir,
>> +                         log_namespace="avocado.qemu.machine")
>>          self.log.debug('QEMUMachine "%s" created', name)
>>          self.log.debug('QEMUMachine "%s" temp_dir: %s', name, vm.temp_dir)
>>          self.log.debug('QEMUMachine "%s" log_dir: %s', name, vm.log_dir)
>> --
>> 2.39.2
>>


-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro

Re: [PATCH 7/8] python/qemu: allow avocado to set logging name space

[John Snow]

On Fri, May 19, 2023 at 2:39 AM Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> John Snow <jsnow@redhat.com> writes:
>
> > On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.bennee@linaro.org> wrote:
> >>
> >> Since the update to the latest version Avocado only automatically
> >> collects logging under the avocado name space. Tweak the QEMUMachine
> >> class to allow avocado to bring logging under its name space. This
> >> also allows useful tricks like:
> >>
> >>   ./avocado --show avocado.qemu.machine run path/to/test
> >>
> >> if you want to quickly get the machine invocation out of a test
> >> without searching deeply through the logs.
> >>
> >
> > Huh. That's kind of weird though, right? Each Python module is
> > intended to log to its own namespace by design; it feels like Avocado
> > really ought to have configuration options that allows it to collect
> > logging from other namespaces. I'm not against this patch, but if for
> > instance I wind up splitting qemu.machine out as a separate module
> > someday (like I did to qemu.qmp), then it feels weird to add options
> > specifically for fudging the logging hierarchy.
>
> According to the docs it does but I couldn't get it to work so this is a
> sticking plaster over that. If it gets fixed in later avocado's it is
> easy enough to remove.
>

Fair enough ...

Cleber, any input?

> > Also, what about the QMP logging? I don't suppose this will trickle
> > down to that level either.
>
> I can certainly add that - but it would need a similar hook.

Right... this is why I am wondering if it isn't just simpler to
configure Avocado to just relay everything from the qemu.* namespace,
which will be easier in the long run ... but hey, if it's broken, it's
broken :(

ACK to the bandaid.

--js

>
> >
> > Worried this is kind of incomplete.
> >
> > --js
> >
> >> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> >> ---
> >>  python/qemu/machine/machine.py         | 42 ++++++++++++++------------
> >>  tests/avocado/avocado_qemu/__init__.py |  3 +-
> >>  2 files changed, 24 insertions(+), 21 deletions(-)
> >>
> >> diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
> >> index e57c254484..402b9a0df9 100644
> >> --- a/python/qemu/machine/machine.py
> >> +++ b/python/qemu/machine/machine.py
> >> @@ -49,10 +49,6 @@
> >>
> >>  from . import console_socket
> >>
> >> -
> >> -LOG = logging.getLogger(__name__)
> >> -
> >> -
> >>  class QEMUMachineError(Exception):
> >>      """
> >>      Exception called when an error in QEMUMachine happens.
> >> @@ -131,6 +127,7 @@ def __init__(self,
> >>                   drain_console: bool = False,
> >>                   console_log: Optional[str] = None,
> >>                   log_dir: Optional[str] = None,
> >> +                 log_namespace: Optional[str] = None,
> >>                   qmp_timer: Optional[float] = 30):
> >>          '''
> >>          Initialize a QEMUMachine
> >> @@ -164,6 +161,11 @@ def __init__(self,
> >>          self._sock_dir = sock_dir
> >>          self._log_dir = log_dir
> >>
> >> +        if log_namespace:
> >> +            self.log = logging.getLogger(log_namespace)
> >> +        else:
> >> +            self.log = logging.getLogger(__name__)
> >> +
> >>          self._monitor_address = monitor_address
> >>
> >>          self._console_log_path = console_log
> >> @@ -382,11 +384,11 @@ def _post_shutdown(self) -> None:
> >>          Called to cleanup the VM instance after the process has exited.
> >>          May also be called after a failed launch.
> >>          """
> >> -        LOG.debug("Cleaning up after VM process")
> >> +        self.log.debug("Cleaning up after VM process")
> >>          try:
> >>              self._close_qmp_connection()
> >>          except Exception as err:  # pylint: disable=broad-except
> >> -            LOG.warning(
> >> +            self.log.warning(
> >>                  "Exception closing QMP connection: %s",
> >>                  str(err) if str(err) else type(err).__name__
> >>              )
> >> @@ -414,7 +416,7 @@ def _post_shutdown(self) -> None:
> >>                  command = ' '.join(self._qemu_full_args)
> >>              else:
> >>                  command = ''
> >> -            LOG.warning(msg, -int(exitcode), command)
> >> +            self.log.warning(msg, -int(exitcode), command)
> >>
> >>          self._quit_issued = False
> >>          self._user_killed = False
> >> @@ -458,7 +460,7 @@ def _launch(self) -> None:
> >>          Launch the VM and establish a QMP connection
> >>          """
> >>          self._pre_launch()
> >> -        LOG.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
> >> +        self.log.debug('VM launch command: %r', ' '.join(self._qemu_full_args))
> >>
> >>          # Cleaning up of this subprocess is guaranteed by _do_shutdown.
> >>          # pylint: disable=consider-using-with
> >> @@ -507,7 +509,7 @@ def _early_cleanup(self) -> None:
> >>          # for QEMU to exit, while QEMU is waiting for the socket to
> >>          # become writable.
> >>          if self._console_socket is not None:
> >> -            LOG.debug("Closing console socket")
> >> +            self.log.debug("Closing console socket")
> >>              self._console_socket.close()
> >>              self._console_socket = None
> >>
> >> @@ -518,7 +520,7 @@ def _hard_shutdown(self) -> None:
> >>          :raise subprocess.Timeout: When timeout is exceeds 60 seconds
> >>              waiting for the QEMU process to terminate.
> >>          """
> >> -        LOG.debug("Performing hard shutdown")
> >> +        self.log.debug("Performing hard shutdown")
> >>          self._early_cleanup()
> >>          self._subp.kill()
> >>          self._subp.wait(timeout=60)
> >> @@ -535,17 +537,17 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
> >>          :raise subprocess.TimeoutExpired: When timeout is exceeded waiting for
> >>              the QEMU process to terminate.
> >>          """
> >> -        LOG.debug("Attempting graceful termination")
> >> +        self.log.debug("Attempting graceful termination")
> >>
> >>          self._early_cleanup()
> >>
> >>          if self._quit_issued:
> >> -            LOG.debug(
> >> +            self.log.debug(
> >>                  "Anticipating QEMU termination due to prior 'quit' command, "
> >>                  "or explicit call to wait()"
> >>              )
> >>          else:
> >> -            LOG.debug("Politely asking QEMU to terminate")
> >> +            self.log.debug("Politely asking QEMU to terminate")
> >>
> >>          if self._qmp_connection:
> >>              try:
> >> @@ -557,14 +559,14 @@ def _soft_shutdown(self, timeout: Optional[int]) -> None:
> >>                  # Regardless, we want to quiesce the connection.
> >>                  self._close_qmp_connection()
> >>          elif not self._quit_issued:
> >> -            LOG.debug(
> >> +            self.log.debug(
> >>                  "Not anticipating QEMU quit and no QMP connection present, "
> >>                  "issuing SIGTERM"
> >>              )
> >>              self._subp.terminate()
> >>
> >>          # May raise subprocess.TimeoutExpired
> >> -        LOG.debug(
> >> +        self.log.debug(
> >>              "Waiting (timeout=%s) for QEMU process (pid=%s) to terminate",
> >>              timeout, self._subp.pid
> >>          )
> >> @@ -586,9 +588,9 @@ def _do_shutdown(self, timeout: Optional[int]) -> None:
> >>              self._soft_shutdown(timeout)
> >>          except Exception as exc:
> >>              if isinstance(exc, subprocess.TimeoutExpired):
> >> -                LOG.debug("Timed out waiting for QEMU process to exit")
> >> -            LOG.debug("Graceful shutdown failed", exc_info=True)
> >> -            LOG.debug("Falling back to hard shutdown")
> >> +                self.log.debug("Timed out waiting for QEMU process to exit")
> >> +            self.log.debug("Graceful shutdown failed", exc_info=True)
> >> +            self.log.debug("Falling back to hard shutdown")
> >>              self._hard_shutdown()
> >>              raise AbnormalShutdown("Could not perform graceful shutdown") \
> >>                  from exc
> >> @@ -611,9 +613,9 @@ def shutdown(self,
> >>          if not self._launched:
> >>              return
> >>
> >> -        LOG.debug("Shutting down VM appliance; timeout=%s", timeout)
> >> +        self.log.debug("Shutting down VM appliance; timeout=%s", timeout)
> >>          if hard:
> >> -            LOG.debug("Caller requests immediate termination of QEMU process.")
> >> +            self.log.debug("Caller requests immediate termination of QEMU process.")
> >>
> >>          try:
> >>              if hard:
> >> diff --git a/tests/avocado/avocado_qemu/__init__.py b/tests/avocado/avocado_qemu/__init__.py
> >> index b19f797b7b..d925573299 100644
> >> --- a/tests/avocado/avocado_qemu/__init__.py
> >> +++ b/tests/avocado/avocado_qemu/__init__.py
> >> @@ -322,7 +322,8 @@ def require_multiprocess(self):
> >>      def _new_vm(self, name, *args):
> >>          self._sd = tempfile.TemporaryDirectory(prefix="qemu_")
> >>          vm = QEMUMachine(self.qemu_bin, base_temp_dir=self.workdir,
> >> -                         sock_dir=self._sd.name, log_dir=self.logdir)
> >> +                         sock_dir=self._sd.name, log_dir=self.logdir,
> >> +                         log_namespace="avocado.qemu.machine")
> >>          self.log.debug('QEMUMachine "%s" created', name)
> >>          self.log.debug('QEMUMachine "%s" temp_dir: %s', name, vm.temp_dir)
> >>          self.log.debug('QEMUMachine "%s" log_dir: %s', name, vm.log_dir)
> >> --
> >> 2.39.2
> >>
>

Re: [PATCH 7/8] python/qemu: allow avocado to set logging name space

[Daniel P. Berrangé]

On Thu, May 18, 2023 at 04:15:03PM -0400, John Snow wrote:
> On Thu, May 18, 2023 at 12:20 PM Alex Bennée <alex.bennee@linaro.org> wrote:
> >
> > Since the update to the latest version Avocado only automatically
> > collects logging under the avocado name space. Tweak the QEMUMachine
> > class to allow avocado to bring logging under its name space. This
> > also allows useful tricks like:
> >
> >   ./avocado --show avocado.qemu.machine run path/to/test
> >
> > if you want to quickly get the machine invocation out of a test
> > without searching deeply through the logs.
> >
> 
> Huh. That's kind of weird though, right? Each Python module is
> intended to log to its own namespace by design; it feels like Avocado
> really ought to have configuration options that allows it to collect
> logging from other namespaces. I'm not against this patch, but if for
> instance I wind up splitting qemu.machine out as a separate module
> someday (like I did to qemu.qmp), then it feels weird to add options
> specifically for fudging the logging hierarchy.

I'd consider this a regression in Avocado. Logging should log
everything from any module by default. Avocado should not presume
that users are only interested in Avocado's own namespace. The
namespaces used by the individuals test are more interesting to
users of Avocado IMHO.

> Also, what about the QMP logging? I don't suppose this will trickle
> down to that level either.
> 
> Worried this is kind of incomplete.

Agreed, I'd push this back onto Avocado to fix the regression.

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