[PATCH 0/7] testing/next (qtest timer stuff)

[PATCH 0/7] testing/next (qtest timer stuff)

[Alex Bennée]

Hi,

Thomas found that a number of tests fail under CFI and other exotic
setups. The eventual realisation was that --enable-slirp masks a lot
of timer misuse because it ensures there is always a timer and
therefor things tend to move on (until the system is shutting down).

It turns out that bc02be4508 wasn't the solution after all. The first
few patches are clean-ups and various tightening of test expectations
before we revert the patch.

Please review:

  Revert "util/timer: avoid deadlock when shutting down"
  tests/qtest: tighten up the checks on clock_step
  tests/qtest: rename qtest_send_prefix and roll-up into qtest_send
  tests/qtest: simplify qtest_process_inbuf
  tests/qtest: don't step clock at start of npcm7xx periodic IRQ test
  tests/qtest: don't attempt to clock_step while waiting for virtio ISR
  tests/docker: replicate the check-rust-tools-nightly CI job

Alex.

Alex Bennée (7):
  tests/docker: replicate the check-rust-tools-nightly CI job
  tests/qtest: don't attempt to clock_step while waiting for virtio ISR
  tests/qtest: don't step clock at start of npcm7xx periodic IRQ test
  tests/qtest: simplify qtest_process_inbuf
  tests/qtest: rename qtest_send_prefix and roll-up into qtest_send
  tests/qtest: tighten up the checks on clock_step
  Revert "util/timer: avoid deadlock when shutting down"

 include/system/qtest.h                 |  1 -
 hw/ppc/spapr_rtas.c                    |  1 -
 hw/riscv/riscv_hart.c                  |  1 -
 system/qtest.c                         | 53 +++++++++-----------------
 tests/qtest/libqos/virtio-pci-modern.c |  6 +--
 tests/qtest/libqos/virtio-pci.c        |  6 +--
 tests/qtest/npcm7xx_timer-test.c       |  1 -
 util/qemu-timer.c                      | 16 ++------
 tests/docker/Makefile.include          |  3 ++
 tests/docker/test-rust                 | 21 ++++++++++
 10 files changed, 48 insertions(+), 61 deletions(-)
 create mode 100755 tests/docker/test-rust

-- 
2.39.5

[PATCH 1/7] tests/docker: replicate the check-rust-tools-nightly CI job

[Alex Bennée]

This allows people to run the test locally:

  make docker-test-rust@fedora-rust-nightly

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 tests/docker/Makefile.include |  3 +++
 tests/docker/test-rust        | 21 +++++++++++++++++++++
 2 files changed, 24 insertions(+)
 create mode 100755 tests/docker/test-rust

diff --git a/tests/docker/Makefile.include b/tests/docker/Makefile.include
index fead7d3abe..fa1cbb6726 100644
--- a/tests/docker/Makefile.include
+++ b/tests/docker/Makefile.include
@@ -236,3 +236,6 @@ docker-image: ${DOCKER_IMAGES:%=docker-image-%}
 
 docker-clean:
 	$(call quiet-command, $(DOCKER_SCRIPT) clean)
+
+# Overrides
+docker-test-rust%: NETWORK=1
diff --git a/tests/docker/test-rust b/tests/docker/test-rust
new file mode 100755
index 0000000000..e7e3e94a55
--- /dev/null
+++ b/tests/docker/test-rust
@@ -0,0 +1,21 @@
+#!/bin/bash -e
+#
+# Run the rust code checks (a.k.a. check-rust-tools-nightly)
+#
+# Copyright (c) 2025 Linaro Ltd
+#
+# Authors:
+#  Alex Bennée <alex.bennee@linaro.org>
+#
+# This work is licensed under the terms of the GNU GPL, version 2
+# or (at your option) any later version. See the COPYING file in
+# the top-level directory.
+
+. common.rc
+
+cd "$BUILD_DIR"
+
+configure_qemu --disable-user --disable-docs --enable-rust
+pyvenv/bin/meson devenv -w $QEMU_SRC/rust ${CARGO-cargo} fmt --check
+make clippy
+make rustdoc
-- 
2.39.5

[PATCH 2/7] tests/qtest: don't attempt to clock_step while waiting for virtio ISR

[Alex Bennée]

This replicates the changes from 92cb8f8bf6 (tests/qtest: remove
clock_steps from virtio tests) as there are no timers in the virtio
code. We still busy wait and timeout though.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 tests/qtest/libqos/virtio-pci-modern.c | 6 ++----
 tests/qtest/libqos/virtio-pci.c        | 6 ++----
 2 files changed, 4 insertions(+), 8 deletions(-)

diff --git a/tests/qtest/libqos/virtio-pci-modern.c b/tests/qtest/libqos/virtio-pci-modern.c
index 18d118866f..f6e3e32891 100644
--- a/tests/qtest/libqos/virtio-pci-modern.c
+++ b/tests/qtest/libqos/virtio-pci-modern.c
@@ -173,13 +173,11 @@ static bool get_config_isr_status(QVirtioDevice *d)
 
 static void wait_config_isr_status(QVirtioDevice *d, gint64 timeout_us)
 {
-    QVirtioPCIDevice *dev = container_of(d, QVirtioPCIDevice, vdev);
     gint64 start_time = g_get_monotonic_time();
 
-    do {
+    while (!get_config_isr_status(d)) {
         g_assert(g_get_monotonic_time() - start_time <= timeout_us);
-        qtest_clock_step(dev->pdev->bus->qts, 100);
-    } while (!get_config_isr_status(d));
+    } 
 }
 
 static void queue_select(QVirtioDevice *d, uint16_t index)
diff --git a/tests/qtest/libqos/virtio-pci.c b/tests/qtest/libqos/virtio-pci.c
index 485b8f6b7e..002bf8b8c2 100644
--- a/tests/qtest/libqos/virtio-pci.c
+++ b/tests/qtest/libqos/virtio-pci.c
@@ -171,13 +171,11 @@ static bool qvirtio_pci_get_config_isr_status(QVirtioDevice *d)
 static void qvirtio_pci_wait_config_isr_status(QVirtioDevice *d,
                                                gint64 timeout_us)
 {
-    QVirtioPCIDevice *dev = container_of(d, QVirtioPCIDevice, vdev);
     gint64 start_time = g_get_monotonic_time();
 
-    do {
+    while (!qvirtio_pci_get_config_isr_status(d)) {
         g_assert(g_get_monotonic_time() - start_time <= timeout_us);
-        qtest_clock_step(dev->pdev->bus->qts, 100);
-    } while (!qvirtio_pci_get_config_isr_status(d));
+    }
 }
 
 static void qvirtio_pci_queue_select(QVirtioDevice *d, uint16_t index)
-- 
2.39.5

Re: [PATCH 2/7] tests/qtest: don't attempt to clock_step while waiting for virtio ISR

[Thomas Huth]

On 20/01/2025 22.02, Alex Bennée wrote:
> This replicates the changes from 92cb8f8bf6 (tests/qtest: remove
> clock_steps from virtio tests) as there are no timers in the virtio
> code. We still busy wait and timeout though.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>   tests/qtest/libqos/virtio-pci-modern.c | 6 ++----
>   tests/qtest/libqos/virtio-pci.c        | 6 ++----
>   2 files changed, 4 insertions(+), 8 deletions(-)
> 
> diff --git a/tests/qtest/libqos/virtio-pci-modern.c b/tests/qtest/libqos/virtio-pci-modern.c
> index 18d118866f..f6e3e32891 100644
> --- a/tests/qtest/libqos/virtio-pci-modern.c
> +++ b/tests/qtest/libqos/virtio-pci-modern.c
> @@ -173,13 +173,11 @@ static bool get_config_isr_status(QVirtioDevice *d)
>   
>   static void wait_config_isr_status(QVirtioDevice *d, gint64 timeout_us)
>   {
> -    QVirtioPCIDevice *dev = container_of(d, QVirtioPCIDevice, vdev);
>       gint64 start_time = g_get_monotonic_time();
>   
> -    do {
> +    while (!get_config_isr_status(d)) {
>           g_assert(g_get_monotonic_time() - start_time <= timeout_us);
> -        qtest_clock_step(dev->pdev->bus->qts, 100);
> -    } while (!get_config_isr_status(d));
> +    } 

Trailing white space in above line?

Apart from that nit:
Reviewed-by: Thomas Huth <thuth@redhat.com>

[PATCH 3/7] tests/qtest: don't step clock at start of npcm7xx periodic IRQ test

[Alex Bennée]

Until there are timers enabled the semantics of clock_step_next() will
fail. Since d524441a36 (system/qtest: properly feedback results of
clock_[step|set]) we will signal a FAIL if time doesn't advance.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 tests/qtest/npcm7xx_timer-test.c | 1 -
 1 file changed, 1 deletion(-)

diff --git a/tests/qtest/npcm7xx_timer-test.c b/tests/qtest/npcm7xx_timer-test.c
index 58f58c2f71..43711049ca 100644
--- a/tests/qtest/npcm7xx_timer-test.c
+++ b/tests/qtest/npcm7xx_timer-test.c
@@ -465,7 +465,6 @@ static void test_periodic_interrupt(gconstpointer test_data)
     int i;
 
     tim_reset(td);
-    clock_step_next();
 
     tim_write_ticr(td, count);
     tim_write_tcsr(td, CEN | IE | MODE_PERIODIC | PRESCALE(ps));
-- 
2.39.5

Re: [PATCH 3/7] tests/qtest: don't step clock at start of npcm7xx periodic IRQ test

[Thomas Huth]

On 20/01/2025 22.02, Alex Bennée wrote:
> Until there are timers enabled the semantics of clock_step_next() will
> fail. Since d524441a36 (system/qtest: properly feedback results of
> clock_[step|set]) we will signal a FAIL if time doesn't advance.
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>   tests/qtest/npcm7xx_timer-test.c | 1 -
>   1 file changed, 1 deletion(-)
> 
> diff --git a/tests/qtest/npcm7xx_timer-test.c b/tests/qtest/npcm7xx_timer-test.c
> index 58f58c2f71..43711049ca 100644
> --- a/tests/qtest/npcm7xx_timer-test.c
> +++ b/tests/qtest/npcm7xx_timer-test.c
> @@ -465,7 +465,6 @@ static void test_periodic_interrupt(gconstpointer test_data)
>       int i;
>   
>       tim_reset(td);
> -    clock_step_next();
>   
>       tim_write_ticr(td, count);
>       tim_write_tcsr(td, CEN | IE | MODE_PERIODIC | PRESCALE(ps));

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

[PATCH 4/7] tests/qtest: simplify qtest_process_inbuf

[Alex Bennée]

Don't both creating a GString to temporarily hold our qtest command.
Instead do a simpler g_strndup and use autofree to clean up
afterwards.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 system/qtest.c | 20 ++++++++------------
 1 file changed, 8 insertions(+), 12 deletions(-)

diff --git a/system/qtest.c b/system/qtest.c
index e68ed0f2a8..bb1efba9fd 100644
--- a/system/qtest.c
+++ b/system/qtest.c
@@ -763,25 +763,21 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
     }
 }
 
+/*
+ * Process as much of @inbuf as we can in newline terminated chunks.
+ * Remove the processed commands from @inbuf as we go.
+ */
 static void qtest_process_inbuf(CharBackend *chr, GString *inbuf)
 {
     char *end;
 
     while ((end = strchr(inbuf->str, '\n')) != NULL) {
-        size_t offset;
-        GString *cmd;
-        gchar **words;
-
-        offset = end - inbuf->str;
+        size_t len = end - inbuf->str;
+        g_autofree char *cmd = g_strndup(inbuf->str, len);
+        g_auto(GStrv) words = g_strsplit(cmd, " ", 0);
 
-        cmd = g_string_new_len(inbuf->str, offset);
-        g_string_erase(inbuf, 0, offset + 1);
-
-        words = g_strsplit(cmd->str, " ", 0);
+        g_string_erase(inbuf, 0, len + 1);
         qtest_process_command(chr, words);
-        g_strfreev(words);
-
-        g_string_free(cmd, TRUE);
     }
 }
 
-- 
2.39.5

[PATCH 5/7] tests/qtest: rename qtest_send_prefix and roll-up into qtest_send

[Alex Bennée]

qtest_send_prefix never actually sent something over the chardev, all
it does is print the timestamp to the QTEST_LOG when enabled. So
rename the function, make it static, remove the unused CharDev and
simplify all the call sites by handling that directly with
qtest_send (and qtest_log_send).

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 include/system/qtest.h |  1 -
 hw/ppc/spapr_rtas.c    |  1 -
 hw/riscv/riscv_hart.c  |  1 -
 system/qtest.c         | 26 +++-----------------------
 4 files changed, 3 insertions(+), 26 deletions(-)

diff --git a/include/system/qtest.h b/include/system/qtest.h
index c161d75165..6ddddc501b 100644
--- a/include/system/qtest.h
+++ b/include/system/qtest.h
@@ -24,7 +24,6 @@ static inline bool qtest_enabled(void)
 }
 
 #ifndef CONFIG_USER_ONLY
-void qtest_send_prefix(CharBackend *chr);
 void G_GNUC_PRINTF(2, 3) qtest_sendf(CharBackend *chr, const char *fmt, ...);
 void qtest_set_command_cb(bool (*pc_cb)(CharBackend *chr, gchar **words));
 bool qtest_driver(void);
diff --git a/hw/ppc/spapr_rtas.c b/hw/ppc/spapr_rtas.c
index df2e837632..503d441b48 100644
--- a/hw/ppc/spapr_rtas.c
+++ b/hw/ppc/spapr_rtas.c
@@ -565,7 +565,6 @@ static bool spapr_qtest_callback(CharBackend *chr, gchar **words)
         g_assert(rc == 0);
         res = qtest_rtas_call(words[1], nargs, args, nret, ret);
 
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "OK %"PRIu64"\n", res);
 
         return true;
diff --git a/hw/riscv/riscv_hart.c b/hw/riscv/riscv_hart.c
index ad67cd7645..a55d156668 100644
--- a/hw/riscv/riscv_hart.c
+++ b/hw/riscv/riscv_hart.c
@@ -94,7 +94,6 @@ static bool csr_qtest_callback(CharBackend *chr, gchar **words)
         g_assert(rc == 0);
         csr_call(words[1], cpu, csr, &val);
 
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "OK 0 "TARGET_FMT_lx"\n", (target_ulong)val);
 
         return true;
diff --git a/system/qtest.c b/system/qtest.c
index bb1efba9fd..28b6fac37c 100644
--- a/system/qtest.c
+++ b/system/qtest.c
@@ -265,7 +265,7 @@ static int hex2nib(char ch)
     }
 }
 
-void qtest_send_prefix(CharBackend *chr)
+static void qtest_log_timestamp(void)
 {
     if (!qtest_log_fp || !qtest_opened) {
         return;
@@ -282,7 +282,7 @@ static void G_GNUC_PRINTF(1, 2) qtest_log_send(const char *fmt, ...)
         return;
     }
 
-    qtest_send_prefix(NULL);
+    qtest_log_timestamp();
 
     va_start(ap, fmt);
     vfprintf(qtest_log_fp, fmt, ap);
@@ -301,6 +301,7 @@ static void qtest_server_char_be_send(void *opaque, const char *str)
 
 static void qtest_send(CharBackend *chr, const char *str)
 {
+    qtest_log_timestamp();
     qtest_server_send(qtest_server_send_opaque, str);
 }
 
@@ -324,7 +325,6 @@ static void qtest_irq_handler(void *opaque, int n, int level)
     if (irq_levels[n] != level) {
         CharBackend *chr = &qtest->qtest_chr;
         irq_levels[n] = level;
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "IRQ %s %d\n",
                     level ? "raise" : "lower", n);
     }
@@ -380,19 +380,16 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         is_outbound = words[0][14] == 'o';
         dev = DEVICE(object_resolve_path(words[1], NULL));
         if (!dev) {
-            qtest_send_prefix(chr);
             qtest_send(chr, "FAIL Unknown device\n");
             return;
         }
 
         if (is_named && !is_outbound) {
-            qtest_send_prefix(chr);
             qtest_send(chr, "FAIL Interception of named in-GPIOs not yet supported\n");
             return;
         }
 
         if (irq_intercept_dev) {
-            qtest_send_prefix(chr);
             if (irq_intercept_dev != dev) {
                 qtest_send(chr, "FAIL IRQ intercept already enabled\n");
             } else {
@@ -419,7 +416,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
             }
         }
 
-        qtest_send_prefix(chr);
         if (interception_succeeded) {
             irq_intercept_dev = dev;
             qtest_send(chr, "OK\n");
@@ -438,7 +434,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
 
         dev = DEVICE(object_resolve_path(words[1], NULL));
         if (!dev) {
-            qtest_send_prefix(chr);
             qtest_send(chr, "FAIL Unknown device\n");
             return;
         }
@@ -457,7 +452,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         irq = qdev_get_gpio_in_named(dev, name, num);
 
         qemu_set_irq(irq, level);
-        qtest_send_prefix(chr);
         qtest_send(chr, "OK\n");
     } else if (strcmp(words[0], "outb") == 0 ||
                strcmp(words[0], "outw") == 0 ||
@@ -480,7 +474,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         } else if (words[0][3] == 'l') {
             cpu_outl(addr, value);
         }
-        qtest_send_prefix(chr);
         qtest_send(chr, "OK\n");
     } else if (strcmp(words[0], "inb") == 0 ||
         strcmp(words[0], "inw") == 0 ||
@@ -501,7 +494,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         } else if (words[0][2] == 'l') {
             value = cpu_inl(addr);
         }
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "OK 0x%04x\n", value);
     } else if (strcmp(words[0], "writeb") == 0 ||
                strcmp(words[0], "writew") == 0 ||
@@ -537,7 +529,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
             address_space_write(first_cpu->as, addr, MEMTXATTRS_UNSPECIFIED,
                                 &data, 8);
         }
-        qtest_send_prefix(chr);
         qtest_send(chr, "OK\n");
     } else if (strcmp(words[0], "readb") == 0 ||
                strcmp(words[0], "readw") == 0 ||
@@ -571,7 +562,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
                                &value, 8);
             tswap64s(&value);
         }
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "OK 0x%016" PRIx64 "\n", value);
     } else if (strcmp(words[0], "read") == 0) {
         g_autoptr(GString) enc = NULL;
@@ -593,7 +583,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
 
         enc = qemu_hexdump_line(NULL, data, len, 0, 0);
 
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "OK 0x%s\n", enc->str);
 
         g_free(data);
@@ -613,7 +602,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         address_space_read(first_cpu->as, addr, MEMTXATTRS_UNSPECIFIED, data,
                            len);
         b64_data = g_base64_encode(data, len);
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "OK %s\n", b64_data);
 
         g_free(data);
@@ -649,7 +637,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
                             len);
         g_free(data);
 
-        qtest_send_prefix(chr);
         qtest_send(chr, "OK\n");
     } else if (strcmp(words[0], "memset") == 0) {
         uint64_t addr, len;
@@ -673,7 +660,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
             g_free(data);
         }
 
-        qtest_send_prefix(chr);
         qtest_send(chr, "OK\n");
     }  else if (strcmp(words[0], "b64write") == 0) {
         uint64_t addr, len;
@@ -705,10 +691,8 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         address_space_write(first_cpu->as, addr, MEMTXATTRS_UNSPECIFIED, data,
                             len);
 
-        qtest_send_prefix(chr);
         qtest_send(chr, "OK\n");
     } else if (strcmp(words[0], "endianness") == 0) {
-        qtest_send_prefix(chr);
         if (target_words_bigendian()) {
             qtest_sendf(chr, "OK big\n");
         } else {
@@ -726,7 +710,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
                                             QEMU_TIMER_ATTR_ALL);
         }
         new_ns = qemu_clock_advance_virtual_time(old_ns + ns);
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "%s %"PRIi64"\n",
                     new_ns > old_ns ? "OK" : "FAIL", new_ns);
     } else if (strcmp(words[0], "module_load") == 0) {
@@ -734,7 +717,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         int rv;
         g_assert(words[1] && words[2]);
 
-        qtest_send_prefix(chr);
         rv = module_load(words[1], words[2], &local_err);
         if (rv > 0) {
             qtest_sendf(chr, "OK\n");
@@ -752,13 +734,11 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         ret = qemu_strtoi64(words[1], NULL, 0, &ns);
         g_assert(ret == 0);
         new_ns = qemu_clock_advance_virtual_time(ns);
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "%s %"PRIi64"\n",
                     new_ns == ns ? "OK" : "FAIL", new_ns);
     } else if (process_command_cb && process_command_cb(chr, words)) {
         /* Command got consumed by the callback handler */
     } else {
-        qtest_send_prefix(chr);
         qtest_sendf(chr, "FAIL Unknown command '%s'\n", words[0]);
     }
 }
-- 
2.39.5

Re: [PATCH 5/7] tests/qtest: rename qtest_send_prefix and roll-up into qtest_send

[Daniel Henrique Barboza]

On 1/20/25 6:02 PM, Alex Bennée wrote:
> qtest_send_prefix never actually sent something over the chardev, all
> it does is print the timestamp to the QTEST_LOG when enabled. So
> rename the function, make it static, remove the unused CharDev and
> simplify all the call sites by handling that directly with
> qtest_send (and qtest_log_send).
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---

Reviewed-by: Daniel Henrique Barboza <dbarboza@ventanamicro.com>

>   include/system/qtest.h |  1 -
>   hw/ppc/spapr_rtas.c    |  1 -
>   hw/riscv/riscv_hart.c  |  1 -
>   system/qtest.c         | 26 +++-----------------------
>   4 files changed, 3 insertions(+), 26 deletions(-)
> 
> diff --git a/include/system/qtest.h b/include/system/qtest.h
> index c161d75165..6ddddc501b 100644
> --- a/include/system/qtest.h
> +++ b/include/system/qtest.h
> @@ -24,7 +24,6 @@ static inline bool qtest_enabled(void)
>   }
>   
>   #ifndef CONFIG_USER_ONLY
> -void qtest_send_prefix(CharBackend *chr);
>   void G_GNUC_PRINTF(2, 3) qtest_sendf(CharBackend *chr, const char *fmt, ...);
>   void qtest_set_command_cb(bool (*pc_cb)(CharBackend *chr, gchar **words));
>   bool qtest_driver(void);
> diff --git a/hw/ppc/spapr_rtas.c b/hw/ppc/spapr_rtas.c
> index df2e837632..503d441b48 100644
> --- a/hw/ppc/spapr_rtas.c
> +++ b/hw/ppc/spapr_rtas.c
> @@ -565,7 +565,6 @@ static bool spapr_qtest_callback(CharBackend *chr, gchar **words)
>           g_assert(rc == 0);
>           res = qtest_rtas_call(words[1], nargs, args, nret, ret);
>   
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "OK %"PRIu64"\n", res);
>   
>           return true;
> diff --git a/hw/riscv/riscv_hart.c b/hw/riscv/riscv_hart.c
> index ad67cd7645..a55d156668 100644
> --- a/hw/riscv/riscv_hart.c
> +++ b/hw/riscv/riscv_hart.c
> @@ -94,7 +94,6 @@ static bool csr_qtest_callback(CharBackend *chr, gchar **words)
>           g_assert(rc == 0);
>           csr_call(words[1], cpu, csr, &val);
>   
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "OK 0 "TARGET_FMT_lx"\n", (target_ulong)val);
>   
>           return true;
> diff --git a/system/qtest.c b/system/qtest.c
> index bb1efba9fd..28b6fac37c 100644
> --- a/system/qtest.c
> +++ b/system/qtest.c
> @@ -265,7 +265,7 @@ static int hex2nib(char ch)
>       }
>   }
>   
> -void qtest_send_prefix(CharBackend *chr)
> +static void qtest_log_timestamp(void)
>   {
>       if (!qtest_log_fp || !qtest_opened) {
>           return;
> @@ -282,7 +282,7 @@ static void G_GNUC_PRINTF(1, 2) qtest_log_send(const char *fmt, ...)
>           return;
>       }
>   
> -    qtest_send_prefix(NULL);
> +    qtest_log_timestamp();
>   
>       va_start(ap, fmt);
>       vfprintf(qtest_log_fp, fmt, ap);
> @@ -301,6 +301,7 @@ static void qtest_server_char_be_send(void *opaque, const char *str)
>   
>   static void qtest_send(CharBackend *chr, const char *str)
>   {
> +    qtest_log_timestamp();
>       qtest_server_send(qtest_server_send_opaque, str);
>   }
>   
> @@ -324,7 +325,6 @@ static void qtest_irq_handler(void *opaque, int n, int level)
>       if (irq_levels[n] != level) {
>           CharBackend *chr = &qtest->qtest_chr;
>           irq_levels[n] = level;
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "IRQ %s %d\n",
>                       level ? "raise" : "lower", n);
>       }
> @@ -380,19 +380,16 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>           is_outbound = words[0][14] == 'o';
>           dev = DEVICE(object_resolve_path(words[1], NULL));
>           if (!dev) {
> -            qtest_send_prefix(chr);
>               qtest_send(chr, "FAIL Unknown device\n");
>               return;
>           }
>   
>           if (is_named && !is_outbound) {
> -            qtest_send_prefix(chr);
>               qtest_send(chr, "FAIL Interception of named in-GPIOs not yet supported\n");
>               return;
>           }
>   
>           if (irq_intercept_dev) {
> -            qtest_send_prefix(chr);
>               if (irq_intercept_dev != dev) {
>                   qtest_send(chr, "FAIL IRQ intercept already enabled\n");
>               } else {
> @@ -419,7 +416,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>               }
>           }
>   
> -        qtest_send_prefix(chr);
>           if (interception_succeeded) {
>               irq_intercept_dev = dev;
>               qtest_send(chr, "OK\n");
> @@ -438,7 +434,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>   
>           dev = DEVICE(object_resolve_path(words[1], NULL));
>           if (!dev) {
> -            qtest_send_prefix(chr);
>               qtest_send(chr, "FAIL Unknown device\n");
>               return;
>           }
> @@ -457,7 +452,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>           irq = qdev_get_gpio_in_named(dev, name, num);
>   
>           qemu_set_irq(irq, level);
> -        qtest_send_prefix(chr);
>           qtest_send(chr, "OK\n");
>       } else if (strcmp(words[0], "outb") == 0 ||
>                  strcmp(words[0], "outw") == 0 ||
> @@ -480,7 +474,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>           } else if (words[0][3] == 'l') {
>               cpu_outl(addr, value);
>           }
> -        qtest_send_prefix(chr);
>           qtest_send(chr, "OK\n");
>       } else if (strcmp(words[0], "inb") == 0 ||
>           strcmp(words[0], "inw") == 0 ||
> @@ -501,7 +494,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>           } else if (words[0][2] == 'l') {
>               value = cpu_inl(addr);
>           }
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "OK 0x%04x\n", value);
>       } else if (strcmp(words[0], "writeb") == 0 ||
>                  strcmp(words[0], "writew") == 0 ||
> @@ -537,7 +529,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>               address_space_write(first_cpu->as, addr, MEMTXATTRS_UNSPECIFIED,
>                                   &data, 8);
>           }
> -        qtest_send_prefix(chr);
>           qtest_send(chr, "OK\n");
>       } else if (strcmp(words[0], "readb") == 0 ||
>                  strcmp(words[0], "readw") == 0 ||
> @@ -571,7 +562,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>                                  &value, 8);
>               tswap64s(&value);
>           }
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "OK 0x%016" PRIx64 "\n", value);
>       } else if (strcmp(words[0], "read") == 0) {
>           g_autoptr(GString) enc = NULL;
> @@ -593,7 +583,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>   
>           enc = qemu_hexdump_line(NULL, data, len, 0, 0);
>   
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "OK 0x%s\n", enc->str);
>   
>           g_free(data);
> @@ -613,7 +602,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>           address_space_read(first_cpu->as, addr, MEMTXATTRS_UNSPECIFIED, data,
>                              len);
>           b64_data = g_base64_encode(data, len);
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "OK %s\n", b64_data);
>   
>           g_free(data);
> @@ -649,7 +637,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>                               len);
>           g_free(data);
>   
> -        qtest_send_prefix(chr);
>           qtest_send(chr, "OK\n");
>       } else if (strcmp(words[0], "memset") == 0) {
>           uint64_t addr, len;
> @@ -673,7 +660,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>               g_free(data);
>           }
>   
> -        qtest_send_prefix(chr);
>           qtest_send(chr, "OK\n");
>       }  else if (strcmp(words[0], "b64write") == 0) {
>           uint64_t addr, len;
> @@ -705,10 +691,8 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>           address_space_write(first_cpu->as, addr, MEMTXATTRS_UNSPECIFIED, data,
>                               len);
>   
> -        qtest_send_prefix(chr);
>           qtest_send(chr, "OK\n");
>       } else if (strcmp(words[0], "endianness") == 0) {
> -        qtest_send_prefix(chr);
>           if (target_words_bigendian()) {
>               qtest_sendf(chr, "OK big\n");
>           } else {
> @@ -726,7 +710,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>                                               QEMU_TIMER_ATTR_ALL);
>           }
>           new_ns = qemu_clock_advance_virtual_time(old_ns + ns);
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "%s %"PRIi64"\n",
>                       new_ns > old_ns ? "OK" : "FAIL", new_ns);
>       } else if (strcmp(words[0], "module_load") == 0) {
> @@ -734,7 +717,6 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>           int rv;
>           g_assert(words[1] && words[2]);
>   
> -        qtest_send_prefix(chr);
>           rv = module_load(words[1], words[2], &local_err);
>           if (rv > 0) {
>               qtest_sendf(chr, "OK\n");
> @@ -752,13 +734,11 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>           ret = qemu_strtoi64(words[1], NULL, 0, &ns);
>           g_assert(ret == 0);
>           new_ns = qemu_clock_advance_virtual_time(ns);
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "%s %"PRIi64"\n",
>                       new_ns == ns ? "OK" : "FAIL", new_ns);
>       } else if (process_command_cb && process_command_cb(chr, words)) {
>           /* Command got consumed by the callback handler */
>       } else {
> -        qtest_send_prefix(chr);
>           qtest_sendf(chr, "FAIL Unknown command '%s'\n", words[0]);
>       }
>   }

[PATCH 6/7] tests/qtest: tighten up the checks on clock_step

[Alex Bennée]

It is invalid to call clock_step with an implied time to step forward
as if no timers are running we won't be able to advance.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 system/qtest.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/system/qtest.c b/system/qtest.c
index 28b6fac37c..1a9bfd0b33 100644
--- a/system/qtest.c
+++ b/system/qtest.c
@@ -708,10 +708,15 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
         } else {
             ns = qemu_clock_deadline_ns_all(QEMU_CLOCK_VIRTUAL,
                                             QEMU_TIMER_ATTR_ALL);
+            if (ns < 0) {
+                qtest_send(chr, "FAIL "
+                           "no timers for clock_step to follow\n");
+                return;
+            }
         }
         new_ns = qemu_clock_advance_virtual_time(old_ns + ns);
         qtest_sendf(chr, "%s %"PRIi64"\n",
-                    new_ns > old_ns ? "OK" : "FAIL", new_ns);
+                    new_ns > old_ns ? "OK" : "FAIL could not advance time", new_ns);
     } else if (strcmp(words[0], "module_load") == 0) {
         Error *local_err = NULL;
         int rv;
-- 
2.39.5

Re: [PATCH 6/7] tests/qtest: tighten up the checks on clock_step

[Peter Maydell]

On Mon, 20 Jan 2025 at 21:02, Alex Bennée <alex.bennee@linaro.org> wrote:
>
> It is invalid to call clock_step with an implied time to step forward
> as if no timers are running we won't be able to advance.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  system/qtest.c | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
>
> diff --git a/system/qtest.c b/system/qtest.c
> index 28b6fac37c..1a9bfd0b33 100644
> --- a/system/qtest.c
> +++ b/system/qtest.c
> @@ -708,10 +708,15 @@ static void qtest_process_command(CharBackend *chr, gchar **words)
>          } else {
>              ns = qemu_clock_deadline_ns_all(QEMU_CLOCK_VIRTUAL,
>                                              QEMU_TIMER_ATTR_ALL);
> +            if (ns < 0) {
> +                qtest_send(chr, "FAIL "
> +                           "no timers for clock_step to follow\n");

I think I would say
"cannot advance clock to the next deadline because there is no pending deadline"
as being a bit clearer about what's gone wrong here.

> +                return;
> +            }
>          }
>          new_ns = qemu_clock_advance_virtual_time(old_ns + ns);
>          qtest_sendf(chr, "%s %"PRIi64"\n",
> -                    new_ns > old_ns ? "OK" : "FAIL", new_ns);
> +                    new_ns > old_ns ? "OK" : "FAIL could not advance time", new_ns);

Maybe we should give up on trying to handle the OK and FAIL
cases in the same qtest_sendf() call? It's not clear to me that
printing the new clock value in the FAIL message is actually
useful.

For that matter, is it actually possible for the clock to not
advance? It doesn't seem obvious that "advance the clock by 0 ticks"
should be a failure case rather than a "does nothing" case,
and once patch 7 is applied I don't think there's any case
where qemu_clock_advance_virtual_time() could make the
clock go backwards... Put another way, this would be moving
back to the situation before your commit d524441a3610b.

thanks
-- PMM

[PATCH 7/7] Revert "util/timer: avoid deadlock when shutting down"

[Alex Bennée]

This reverts commit bc02be4508d8753d1f6071b77d10f4661587df6f.

Now we catch attempts to clock_step to the next timer when none are
enabled we can revert the previous attempt to prevent deadlock. As
long as a new target time is given we will move time forward even if
no timers will fire. This is desirable for tests which are checking
that nothing changes when things are disabled.

Previously most tests got away with it because --enable-slirp always
has a timer running while the test is active.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Cc: Peter Maydell <peter.maydell@linaro.org>
---
 util/qemu-timer.c | 16 +++-------------
 1 file changed, 3 insertions(+), 13 deletions(-)

diff --git a/util/qemu-timer.c b/util/qemu-timer.c
index 0e8a453eaa..3243d2c515 100644
--- a/util/qemu-timer.c
+++ b/util/qemu-timer.c
@@ -675,17 +675,10 @@ int64_t qemu_clock_advance_virtual_time(int64_t dest)
 {
     int64_t clock = qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL);
     AioContext *aio_context;
-    int64_t deadline;
-
     aio_context = qemu_get_aio_context();
-
-    deadline = qemu_clock_deadline_ns_all(QEMU_CLOCK_VIRTUAL,
-                                          QEMU_TIMER_ATTR_ALL);
-    /*
-     * A deadline of < 0 indicates this timer is not enabled, so we
-     * won't get far trying to run it forward.
-     */
-    while (deadline >= 0 && clock < dest) {
+    while (clock < dest) {
+        int64_t deadline = qemu_clock_deadline_ns_all(QEMU_CLOCK_VIRTUAL,
+                                                      QEMU_TIMER_ATTR_ALL);
         int64_t warp = qemu_soonest_timeout(dest - clock, deadline);
 
         qemu_virtual_clock_set_ns(qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) + warp);
@@ -693,9 +686,6 @@ int64_t qemu_clock_advance_virtual_time(int64_t dest)
         qemu_clock_run_timers(QEMU_CLOCK_VIRTUAL);
         timerlist_run_timers(aio_context->tlg.tl[QEMU_CLOCK_VIRTUAL]);
         clock = qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL);
-
-        deadline = qemu_clock_deadline_ns_all(QEMU_CLOCK_VIRTUAL,
-                                              QEMU_TIMER_ATTR_ALL);
     }
     qemu_clock_notify(QEMU_CLOCK_VIRTUAL);
 
-- 
2.39.5

Re: [PATCH 0/7] testing/next (qtest timer stuff)

[Thomas Huth]

On 20/01/2025 22.02, Alex Bennée wrote:
> Hi,
> 
> Thomas found that a number of tests fail under CFI and other exotic
> setups. The eventual realisation was that --enable-slirp masks a lot
> of timer misuse because it ensures there is always a timer and
> therefor things tend to move on (until the system is shutting down).
> 
> It turns out that bc02be4508 wasn't the solution after all. The first
> few patches are clean-ups and various tightening of test expectations
> before we revert the patch.
> 
> Please review:
> 
>    Revert "util/timer: avoid deadlock when shutting down"
>    tests/qtest: tighten up the checks on clock_step
>    tests/qtest: rename qtest_send_prefix and roll-up into qtest_send
>    tests/qtest: simplify qtest_process_inbuf
>    tests/qtest: don't step clock at start of npcm7xx periodic IRQ test
>    tests/qtest: don't attempt to clock_step while waiting for virtio ISR
>    tests/docker: replicate the check-rust-tools-nightly CI job
> 
> Alex.
> 
> Alex Bennée (7):
>    tests/docker: replicate the check-rust-tools-nightly CI job
>    tests/qtest: don't attempt to clock_step while waiting for virtio ISR
>    tests/qtest: don't step clock at start of npcm7xx periodic IRQ test
>    tests/qtest: simplify qtest_process_inbuf
>    tests/qtest: rename qtest_send_prefix and roll-up into qtest_send
>    tests/qtest: tighten up the checks on clock_step
>    Revert "util/timer: avoid deadlock when shutting down"

Thanks, I've checked that this fixes the check-cfi-* CI jobs and it also 
seems to help with the travis jobs that use --disable-slirp:

  https://app.travis-ci.com/github/huth/qemu/builds/273921493

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

Re: [PATCH 0/7] testing/next (qtest timer stuff)

[Fabiano Rosas]

Alex Bennée <alex.bennee@linaro.org> writes:

> Hi,
>
> Thomas found that a number of tests fail under CFI and other exotic
> setups. The eventual realisation was that --enable-slirp masks a lot
> of timer misuse because it ensures there is always a timer and
> therefor things tend to move on (until the system is shutting down).
>
> It turns out that bc02be4508 wasn't the solution after all. The first
> few patches are clean-ups and various tightening of test expectations
> before we revert the patch.
>
> Please review:
>
>   Revert "util/timer: avoid deadlock when shutting down"
>   tests/qtest: tighten up the checks on clock_step
>   tests/qtest: rename qtest_send_prefix and roll-up into qtest_send
>   tests/qtest: simplify qtest_process_inbuf
>   tests/qtest: don't step clock at start of npcm7xx periodic IRQ test
>   tests/qtest: don't attempt to clock_step while waiting for virtio ISR
>   tests/docker: replicate the check-rust-tools-nightly CI job
>
> Alex.
>
> Alex Bennée (7):
>   tests/docker: replicate the check-rust-tools-nightly CI job
>   tests/qtest: don't attempt to clock_step while waiting for virtio ISR
>   tests/qtest: don't step clock at start of npcm7xx periodic IRQ test
>   tests/qtest: simplify qtest_process_inbuf
>   tests/qtest: rename qtest_send_prefix and roll-up into qtest_send
>   tests/qtest: tighten up the checks on clock_step
>   Revert "util/timer: avoid deadlock when shutting down"
>
>  include/system/qtest.h                 |  1 -
>  hw/ppc/spapr_rtas.c                    |  1 -
>  hw/riscv/riscv_hart.c                  |  1 -
>  system/qtest.c                         | 53 +++++++++-----------------
>  tests/qtest/libqos/virtio-pci-modern.c |  6 +--
>  tests/qtest/libqos/virtio-pci.c        |  6 +--
>  tests/qtest/npcm7xx_timer-test.c       |  1 -
>  util/qemu-timer.c                      | 16 ++------
>  tests/docker/Makefile.include          |  3 ++
>  tests/docker/test-rust                 | 21 ++++++++++
>  10 files changed, 48 insertions(+), 61 deletions(-)
>  create mode 100755 tests/docker/test-rust

Series:

Acked-by: Fabiano Rosas <farosas@suse.de>