[PATCH v3 19/20] util: add support for formatting thread info in messages

Daniel P. Berrangé posted 20 patches 2 weeks, 3 days ago
Maintainers: Gerd Hoffmann <kraxel@redhat.com>, Christian Schoenebeck <qemu_oss@crudebyte.com>, Markus Armbruster <armbru@redhat.com>, Paolo Bonzini <pbonzini@redhat.com>, "Marc-André Lureau" <marcandre.lureau@redhat.com>, "Daniel P. Berrangé" <berrange@redhat.com>, "Philippe Mathieu-Daudé" <philmd@linaro.org>, "Dr. David Alan Gilbert" <dave@treblig.org>, Kevin Wolf <kwolf@redhat.com>, Hanna Reitz <hreitz@redhat.com>, Stefan Weil <sw@weilnetz.de>
There is a newer version of this series
[PATCH v3 19/20] util: add support for formatting thread info in messages
Posted by Daniel P. Berrangé 2 weeks, 3 days ago
The message context is now extended to be able to include the
thread ID and thread name, after the program name. On Linux
the thread ID will match the process TID visible in /proc,
while on other platforms it will merely be an integer repr
of the system thread object address/ID.

This changes the output for both error_report and qemu_log,
when running under the system emulators or the QEMU storage
daemon. Other programs omit the thread information since
they are largely single threaded, though potentially it
would be useful to enable in all of them, given that the RCU
thread will always get spawned by a constructor function.

Before:

  # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*'
  qemu-system-x86_64: qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x560db818e080 dir=fish
  qemu-system-x86_64: qcrypto_tls_creds_get_path TLS creds path creds=0x560db818e080 filename=ca-cert.pem path=<none>
  qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory

After:

  # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*'
  qemu-system-x86_64(772366:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x560db818e080 dir=fish
  qemu-system-x86_64(772366:main): qcrypto_tls_creds_get_path TLS creds path creds=0x560db818e080 filename=ca-cert.pem path=<none>
  qemu-system-x86_64(772366:main): Unable to access credentials fish/ca-cert.pem: No such file or directory

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 include/qemu/message.h               | 1 +
 storage-daemon/qemu-storage-daemon.c | 6 ++++++
 system/vl.c                          | 8 ++++++--
 tests/qemu-iotests/041               | 2 +-
 tests/qemu-iotests/common.filter     | 2 +-
 util/message.c                       | 7 +++++++
 6 files changed, 22 insertions(+), 4 deletions(-)

diff --git a/include/qemu/message.h b/include/qemu/message.h
index b8518d06be..2cc092c993 100644
--- a/include/qemu/message.h
+++ b/include/qemu/message.h
@@ -7,6 +7,7 @@ enum QMessageFormatFlags {
     QMESSAGE_FORMAT_TIMESTAMP = (1 << 0),
     QMESSAGE_FORMAT_WORKLOAD_NAME = (1 << 1),
     QMESSAGE_FORMAT_PROGRAM_NAME = (1 << 2),
+    QMESSAGE_FORMAT_THREAD_INFO = (1 << 3),
 };
 
 /**
diff --git a/storage-daemon/qemu-storage-daemon.c b/storage-daemon/qemu-storage-daemon.c
index eb72561358..cc44ed7848 100644
--- a/storage-daemon/qemu-storage-daemon.c
+++ b/storage-daemon/qemu-storage-daemon.c
@@ -47,6 +47,7 @@
 #include "qemu/cutils.h"
 #include "qemu/config-file.h"
 #include "qemu/error-report.h"
+#include "qemu/message.h"
 #include "qemu/help_option.h"
 #include "qemu/job.h"
 #include "qemu/log.h"
@@ -65,6 +66,10 @@ static const char *pid_file;
 static char *pid_file_realpath;
 static volatile bool exit_requested = false;
 
+#define QMESSAGE_FORMAT_DEFAULT \
+    (QMESSAGE_FORMAT_PROGRAM_NAME | \
+     QMESSAGE_FORMAT_THREAD_INFO)
+
 void qemu_system_killed(int signal, pid_t pid)
 {
     exit_requested = true;
@@ -399,6 +404,7 @@ int main(int argc, char *argv[])
 #endif
 
     error_init(argv[0]);
+    qmessage_set_format(QMESSAGE_FORMAT_DEFAULT);
     qemu_init_exec_dir(argv[0]);
     os_setup_signal_handling();
 
diff --git a/system/vl.c b/system/vl.c
index 9030212c50..20b655a7bc 100644
--- a/system/vl.c
+++ b/system/vl.c
@@ -145,6 +145,10 @@
 
 #define MAX_VIRTIO_CONSOLES 1
 
+#define QMESSAGE_FORMAT_DEFAULT \
+    (QMESSAGE_FORMAT_PROGRAM_NAME | \
+     QMESSAGE_FORMAT_THREAD_INFO)
+
 typedef struct BlockdevOptionsQueueEntry {
     BlockdevOptions *bdo;
     Location loc;
@@ -811,10 +815,9 @@ static void realtime_init(void)
     }
 }
 
-
 static void configure_msg(QemuOpts *opts)
 {
-    int flags = QMESSAGE_FORMAT_PROGRAM_NAME;
+    int flags = QMESSAGE_FORMAT_DEFAULT;
     if (qemu_opt_get_bool(opts, "timestamp", false)) {
         flags |= QMESSAGE_FORMAT_TIMESTAMP;
     }
@@ -2888,6 +2891,7 @@ void qemu_init(int argc, char **argv)
     module_call_init(MODULE_INIT_OPTS);
 
     error_init(argv[0]);
+    qmessage_set_format(QMESSAGE_FORMAT_DEFAULT);
     qemu_init_exec_dir(argv[0]);
 
     os_setup_limits();
diff --git a/tests/qemu-iotests/041 b/tests/qemu-iotests/041
index 8452845f44..dc2666afe7 100755
--- a/tests/qemu-iotests/041
+++ b/tests/qemu-iotests/041
@@ -1102,7 +1102,7 @@ class TestRepairQuorum(iotests.QMPTestCase):
         self.vm.shutdown()
         log = iotests.filter_qtest(self.vm.get_log())
         log = re.sub(r'^Formatting.*\n', '', log)
-        log = re.sub(r'^%s: ' % os.path.basename(iotests.qemu_prog), '', log)
+        log = re.sub(r'^%s: \(\d+:\w+\): ' % os.path.basename(iotests.qemu_prog), '', log)
 
         self.assertEqual(log,
                          "Can no longer replace 'img1' by 'repair0', because " +
diff --git a/tests/qemu-iotests/common.filter b/tests/qemu-iotests/common.filter
index 511a55b1e8..84f352d30b 100644
--- a/tests/qemu-iotests/common.filter
+++ b/tests/qemu-iotests/common.filter
@@ -81,7 +81,7 @@ _filter_qemu_io()
 # replace occurrences of QEMU_PROG with "qemu"
 _filter_qemu()
 {
-    gsed -e "s#\\(^\\|(qemu) \\)$(basename $QEMU_PROG):#\1QEMU_PROG:#" \
+    gsed -e "s#\\(^\\|(qemu) \\)$(basename $QEMU_PROG): ([0-9]\+:[-_a-zA-Z]\+):#\1QEMU_PROG:#" \
         -e 's#^QEMU [0-9]\+\.[0-9]\+\.[0-9]\+ monitor#QEMU X.Y.Z monitor#' \
         -e $'s#\r##' # QEMU monitor uses \r\n line endings
 }
diff --git a/util/message.c b/util/message.c
index 1db9254733..814ca0316e 100644
--- a/util/message.c
+++ b/util/message.c
@@ -37,4 +37,11 @@ void qmessage_context_print(FILE *fp)
             fprintf(fp, "%s: ", pgnamestr);
         }
     }
+
+    if (message_format & QMESSAGE_FORMAT_THREAD_INFO) {
+        int thid = qemu_get_thread_id();
+        const char *thname = qemu_thread_get_name();
+
+        fprintf(fp, "(%d:%s): ", thid, thname);
+    }
 }
-- 
2.50.1


Re: [PATCH v3 19/20] util: add support for formatting thread info in messages
Posted by Richard Henderson 2 weeks, 2 days ago
On 9/10/25 18:03, Daniel P. Berrangé wrote:
> --- a/storage-daemon/qemu-storage-daemon.c
> +++ b/storage-daemon/qemu-storage-daemon.c
> @@ -47,6 +47,7 @@
>   #include "qemu/cutils.h"
>   #include "qemu/config-file.h"
>   #include "qemu/error-report.h"
> +#include "qemu/message.h"
>   #include "qemu/help_option.h"
>   #include "qemu/job.h"
>   #include "qemu/log.h"
> @@ -65,6 +66,10 @@ static const char *pid_file;
>   static char *pid_file_realpath;
>   static volatile bool exit_requested = false;
>   
> +#define QMESSAGE_FORMAT_DEFAULT \
> +    (QMESSAGE_FORMAT_PROGRAM_NAME | \
> +     QMESSAGE_FORMAT_THREAD_INFO)
> +
>   void qemu_system_killed(int signal, pid_t pid)
>   {
>       exit_requested = true;
> @@ -399,6 +404,7 @@ int main(int argc, char *argv[])
>   #endif
>   
>       error_init(argv[0]);
> +    qmessage_set_format(QMESSAGE_FORMAT_DEFAULT);
>       qemu_init_exec_dir(argv[0]);
>       os_setup_signal_handling();
>   
> diff --git a/system/vl.c b/system/vl.c
> index 9030212c50..20b655a7bc 100644
> --- a/system/vl.c
> +++ b/system/vl.c
> @@ -145,6 +145,10 @@
>   
>   #define MAX_VIRTIO_CONSOLES 1
>   
> +#define QMESSAGE_FORMAT_DEFAULT \
> +    (QMESSAGE_FORMAT_PROGRAM_NAME | \
> +     QMESSAGE_FORMAT_THREAD_INFO)
> +
>   typedef struct BlockdevOptionsQueueEntry {
>       BlockdevOptions *bdo;
>       Location loc;
> @@ -811,10 +815,9 @@ static void realtime_init(void)
>       }
>   }
>   
> -
>   static void configure_msg(QemuOpts *opts)
>   {
> -    int flags = QMESSAGE_FORMAT_PROGRAM_NAME;
> +    int flags = QMESSAGE_FORMAT_DEFAULT;
>       if (qemu_opt_get_bool(opts, "timestamp", false)) {
>           flags |= QMESSAGE_FORMAT_TIMESTAMP;
>       }
> @@ -2888,6 +2891,7 @@ void qemu_init(int argc, char **argv)
>       module_call_init(MODULE_INIT_OPTS);
>   
>       error_init(argv[0]);
> +    qmessage_set_format(QMESSAGE_FORMAT_DEFAULT);

Worth a static initial value of the variable, rather than require two other startup calls?

This also seems like it should be a separate patch from adding THREAD_INFO to 
qmessage_context_print.


r~


>       qemu_init_exec_dir(argv[0]);
>   
>       os_setup_limits();
> diff --git a/tests/qemu-iotests/041 b/tests/qemu-iotests/041
> index 8452845f44..dc2666afe7 100755
> --- a/tests/qemu-iotests/041
> +++ b/tests/qemu-iotests/041
> @@ -1102,7 +1102,7 @@ class TestRepairQuorum(iotests.QMPTestCase):
>           self.vm.shutdown()
>           log = iotests.filter_qtest(self.vm.get_log())
>           log = re.sub(r'^Formatting.*\n', '', log)
> -        log = re.sub(r'^%s: ' % os.path.basename(iotests.qemu_prog), '', log)
> +        log = re.sub(r'^%s: \(\d+:\w+\): ' % os.path.basename(iotests.qemu_prog), '', log)
>   
>           self.assertEqual(log,
>                            "Can no longer replace 'img1' by 'repair0', because " +
> diff --git a/tests/qemu-iotests/common.filter b/tests/qemu-iotests/common.filter
> index 511a55b1e8..84f352d30b 100644
> --- a/tests/qemu-iotests/common.filter
> +++ b/tests/qemu-iotests/common.filter
> @@ -81,7 +81,7 @@ _filter_qemu_io()
>   # replace occurrences of QEMU_PROG with "qemu"
>   _filter_qemu()
>   {
> -    gsed -e "s#\\(^\\|(qemu) \\)$(basename $QEMU_PROG):#\1QEMU_PROG:#" \
> +    gsed -e "s#\\(^\\|(qemu) \\)$(basename $QEMU_PROG): ([0-9]\+:[-_a-zA-Z]\+):#\1QEMU_PROG:#" \
>           -e 's#^QEMU [0-9]\+\.[0-9]\+\.[0-9]\+ monitor#QEMU X.Y.Z monitor#' \
>           -e $'s#\r##' # QEMU monitor uses \r\n line endings
>   }
> diff --git a/util/message.c b/util/message.c
> index 1db9254733..814ca0316e 100644
> --- a/util/message.c
> +++ b/util/message.c
> @@ -37,4 +37,11 @@ void qmessage_context_print(FILE *fp)
>               fprintf(fp, "%s: ", pgnamestr);
>           }
>       }
> +
> +    if (message_format & QMESSAGE_FORMAT_THREAD_INFO) {
> +        int thid = qemu_get_thread_id();
> +        const char *thname = qemu_thread_get_name();
> +
> +        fprintf(fp, "(%d:%s): ", thid, thname);
> +    }
>   }


Re: [PATCH v3 19/20] util: add support for formatting thread info in messages
Posted by Daniel P. Berrangé 2 weeks, 2 days ago
On Thu, Sep 11, 2025 at 06:11:47PM +0000, Richard Henderson wrote:
> On 9/10/25 18:03, Daniel P. Berrangé wrote:
> > --- a/storage-daemon/qemu-storage-daemon.c
> > +++ b/storage-daemon/qemu-storage-daemon.c
> > @@ -47,6 +47,7 @@
> >   #include "qemu/cutils.h"
> >   #include "qemu/config-file.h"
> >   #include "qemu/error-report.h"
> > +#include "qemu/message.h"
> >   #include "qemu/help_option.h"
> >   #include "qemu/job.h"
> >   #include "qemu/log.h"
> > @@ -65,6 +66,10 @@ static const char *pid_file;
> >   static char *pid_file_realpath;
> >   static volatile bool exit_requested = false;
> > +#define QMESSAGE_FORMAT_DEFAULT \
> > +    (QMESSAGE_FORMAT_PROGRAM_NAME | \
> > +     QMESSAGE_FORMAT_THREAD_INFO)
> > +
> >   void qemu_system_killed(int signal, pid_t pid)
> >   {
> >       exit_requested = true;
> > @@ -399,6 +404,7 @@ int main(int argc, char *argv[])
> >   #endif
> >       error_init(argv[0]);
> > +    qmessage_set_format(QMESSAGE_FORMAT_DEFAULT);
> >       qemu_init_exec_dir(argv[0]);
> >       os_setup_signal_handling();
> > diff --git a/system/vl.c b/system/vl.c
> > index 9030212c50..20b655a7bc 100644
> > --- a/system/vl.c
> > +++ b/system/vl.c
> > @@ -145,6 +145,10 @@
> >   #define MAX_VIRTIO_CONSOLES 1
> > +#define QMESSAGE_FORMAT_DEFAULT \
> > +    (QMESSAGE_FORMAT_PROGRAM_NAME | \
> > +     QMESSAGE_FORMAT_THREAD_INFO)
> > +
> >   typedef struct BlockdevOptionsQueueEntry {
> >       BlockdevOptions *bdo;
> >       Location loc;
> > @@ -811,10 +815,9 @@ static void realtime_init(void)
> >       }
> >   }
> > -
> >   static void configure_msg(QemuOpts *opts)
> >   {
> > -    int flags = QMESSAGE_FORMAT_PROGRAM_NAME;
> > +    int flags = QMESSAGE_FORMAT_DEFAULT;
> >       if (qemu_opt_get_bool(opts, "timestamp", false)) {
> >           flags |= QMESSAGE_FORMAT_TIMESTAMP;
> >       }
> > @@ -2888,6 +2891,7 @@ void qemu_init(int argc, char **argv)
> >       module_call_init(MODULE_INIT_OPTS);
> >       error_init(argv[0]);
> > +    qmessage_set_format(QMESSAGE_FORMAT_DEFAULT);
> 
> Worth a static initial value of the variable, rather than require two other startup calls?

NB, the qmessage stuff is linked into all our other binaries too,
and so I only wanted to turn on thread info for the subset of
binaries that are likely to be using multiple threads. Then
again, posibly both qemu-nbd and qemu-img might use threads
in some scenarios

> This also seems like it should be a separate patch from adding THREAD_INFO
> to qmessage_context_print.

Sure, I can do that.


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