[PATCH v5 00/24] util: sync error_report & qemu_log output more closely
This series is a tangent that came out of discussion in https://lists.nongnu.org/archive/html/qemu-devel/2025-08/msg00903.html In thinking about adding thread info to error_report, I came to realize we should likely make qemu_log behave consistently with error_report & friends. We already honour '-msg timestamp=on', but don't honour 'guest-name=on' and also don't include the binary name. As an example of the current state, consider mixing error and log output today: - Default context: # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \ -d 'trace:qcrypto*' qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55ac6d97f700 dir=fish qcrypto_tls_creds_get_path TLS creds path creds=0x55ac6d97f700 filename=ca-cert.pem path=<none> qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory - Full context: # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \ -d 'trace:qcrypto*' \ -msg guest-name=on,timestamp=on \ -name "fish food" 2025-08-19T20:14:16.791413Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55e9a3458d10 dir=fish 2025-08-19T20:14:16.791429Z qcrypto_tls_creds_get_path TLS creds path creds=0x55e9a3458d10 filename=ca-cert.pem path=<none> 2025-08-19T20:14:16.791433Z fish food qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory And after this series is complete: - Default context: # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \ -d 'trace:qcrypto*' qemu-system-x86_64(1184284:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55a24ad5cb30 dir=fish qemu-system-x86_64(1184284:main): qcrypto_tls_creds_get_path TLS creds path creds=0x55a24ad5cb30 filename=ca-cert.pem path=<none> qemu-system-x86_64(1184284:main): Unable to access credentials fish/ca-cert.pem: No such file or directory - Full context: # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \ -d 'trace:qcrypto*' \ -msg guest-name=on,timestamp=on \ -name "fish food" 2025-08-19T20:12:50.211823Z [fish food] qemu-system-x86_64(1168876:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x5582183d8760 dir=fish 2025-08-19T20:12:50.211842Z [fish food] qemu-system-x86_64(1168876:main): qcrypto_tls_creds_get_path TLS creds path creds=0x5582183d8760 filename=ca-cert.pem +path=<none> 2025-08-19T20:12:50.211846Z [fish food] qemu-system-x86_64(1168876:main): Unable to access credentials fish/ca-cert.pem: No such file or directory The main things to note: * error_report/warn_report/qemu_log share the same output format and -msg applies to both * -msg debug-threads=on is now unconditionally enabled and thus the param is deprecated & ignored * Thread ID and name are unconditionally enabled * Guest name is surrounded in [...] brackets * The default output lines are typically 15 chars wider given that we always include the thread ID + name now * This takes the liberty of assigning the new file to the existing error-report.c maintainer (Markus) Since splitting it off into message.c instead of putting it all in error-report.c felt slightly nicer. One thing I didn't tackle is making the location info get reported for qemu_log. This is used to give context for error messages when parsing some CLI args, and could be interesting for log messages associated with those same CLI args. Changes in v5: - Remove redundant [] around values in qemu-options.hx - Use g_strlcpy instead of strlcpy - Remove redundant !! around a value that was already bool - Improve the qemu_lock_trylock() API docs to encourage use of fprintf() instead of further qemu_log() calls - Add a qemu_log_trylock_context() counterpart for qemu_log_trylock that includes the message context - Don't scan for \n to determine whether we can output a message context prefix or not. Instead track call depth on qemu_log_trylock() and only output it when the depth was initially zero. This fixes linux-user -strace output formatting which was mangled by v4 - Use fprintf(stderr) instead of error_printf_mon in cases where mon would be NULL - Use fputs/fputc in simple cases where we don't need the full power of fprintf - Use qemu_f{un}lockfile instead of f{un}lockfile - Add -msg thread-info=on|off,program-name=on|off args to allow default message prefixes to be optionally disabled Changes in v4: - Re-architected the way error_vprintf() operates to simplify monitor dependency - Fixed the move of error_vprintf from monitor.c to error-report.c so that unit tests can still get a stub to capture messages to g_test_message - Simplify changes to vreport() to avoid passing around function pointers - Add locking of stderr to vreport() to serialize incremental output - Fix thread naming logic changes on Windows - Change deprecation warning messages Changes in v3: - Stop formatting a string in qmessage_context, instead output directly to a "FILE *" stream - Fix pre-existing bug interleaving qemu_log and vreport when the trace 'log' backend has mutex probes enabled Changes in v2: - Re-use existing qemu_get_thread_id rather than re-inventing it as qemu_thread_get_id. - Expose qemu_thread_set_name and use it from all locations needing to set thread names - Fix qemu_log() to skip context prefix when emitting a log message in fragments across multiple calls - Skip allocating memory for empty context messages - Fix leak in win32 impl of qemu_thread_get_name - Use g_strlcpy where possible Daniel P. Berrangé (24): qemu-options: remove extraneous [] around arg values include: define constant for early constructor priority monitor: initialize global data from a constructor system: unconditionally enable thread naming util: expose qemu_thread_set_name audio: make jackaudio use qemu_thread_set_name util: set the name for the 'main' thread util: add API to fetch the current thread name util: introduce some API docs for logging APIs util: avoid repeated prefix on incremental qemu_log calls ui/vnc: remove use of error_printf_unless_qmp() monitor: remove redundant error_[v]printf_unless_qmp monitor: refactor error_vprintf() monitor: move error_vprintf back to error-report.c monitor: introduce monitor_cur_is_hmp() helper util: don't skip error prefixes when QMP is active util: fix interleaving of error & trace output util: fix interleaving of error prefixes util: introduce common helper for error-report & log code util: convert error-report & log to message API for timestamp util: add support for formatting a workload name in messages util: add support for formatting a program name in messages util: add support for formatting thread info in messages util: add brackets around guest name in message context MAINTAINERS | 2 + audio/jackaudio.c | 30 +++++-- docs/about/deprecated.rst | 7 ++ include/monitor/monitor.h | 4 +- include/qemu/compiler.h | 8 ++ include/qemu/error-report.h | 4 - include/qemu/log-for-trace.h | 17 +++- include/qemu/log.h | 38 +++++++++ include/qemu/message.h | 40 +++++++++ include/qemu/thread.h | 3 +- meson.build | 21 +++++ monitor/monitor.c | 61 +++++--------- qemu-options.hx | 121 ++++++++++++++------------- rust/util/src/log.rs | 6 ++ storage-daemon/qemu-storage-daemon.c | 6 ++ stubs/error-printf.c | 23 ----- stubs/meson.build | 1 - stubs/monitor-core.c | 20 ++++- system/vl.c | 49 +++++++++-- tests/qemu-iotests/041 | 2 +- tests/qemu-iotests/common.filter | 2 +- tests/unit/test-error-report.c | 6 +- tests/unit/test-util-sockets.c | 1 + ui/vnc.c | 14 ++-- util/error-report.c | 97 ++++++++++++--------- util/log.c | 47 ++++++----- util/meson.build | 1 + util/message.c | 51 +++++++++++ util/qemu-thread-posix.c | 77 +++++++++++------ util/qemu-thread-win32.c | 87 +++++++++++++------ 30 files changed, 580 insertions(+), 266 deletions(-) create mode 100644 include/qemu/message.h delete mode 100644 stubs/error-printf.c create mode 100644 util/message.c -- 2.52.0
There are quite a few inappropriate uses of [...] around argument values. The [] are intended to indicate optionality, but in some cases it is used to wrap a set of enum values. In other cases it is being used to show the value is entirely optional, which was common behaviour for boolean values in the past. QEMU has deprecated short-form boolean options for quite a while though, and we should thus not advertize this possibility in the docs. Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- qemu-options.hx | 110 ++++++++++++++++++++++++------------------------ 1 file changed, 55 insertions(+), 55 deletions(-) diff --git a/qemu-options.hx b/qemu-options.hx index ec92723f10..e8057fdcc9 100644 --- a/qemu-options.hx +++ b/qemu-options.hx @@ -25,7 +25,7 @@ SRST ERST DEF("machine", HAS_ARG, QEMU_OPTION_machine, \ - "-machine [type=]name[,prop[=value][,...]]\n" + "-machine [type=]name[,prop=value[,...]]\n" " selects emulated machine ('-machine help' for list)\n" " property accel=accel1[:accel2[:...]] selects accelerator\n" " supported accelerators are kvm, xen, hvf, nvmm, whpx, mshv or tcg (default: tcg)\n" @@ -227,7 +227,7 @@ SRST ERST DEF("accel", HAS_ARG, QEMU_OPTION_accel, - "-accel [accel=]accelerator[,prop[=value][,...]]\n" + "-accel [accel=]accelerator[,prop=value[,...]]\n" " select accelerator (kvm, xen, hvf, nvmm, whpx, mshv or tcg; use 'help' for a list)\n" " igd-passthru=on|off (enable Xen integrated Intel graphics passthrough, default=off)\n" " kernel-irqchip=on|off|split controls accelerated irqchip support (default=on)\n" @@ -789,17 +789,17 @@ ERST DEF("audio", HAS_ARG, QEMU_OPTION_audio, - "-audio [driver=]driver[,prop[=value][,...]]\n" + "-audio [driver=]driver[,prop=value[,...]]\n" " specifies default audio backend when `audiodev` is not\n" " used to create a machine or sound device;" " options are the same as for -audiodev\n" - "-audio [driver=]driver,model=value[,prop[=value][,...]]\n" + "-audio [driver=]driver,model=value[,prop=value[,...]]\n" " specifies the audio backend and device to use;\n" " apart from 'model', options are the same as for -audiodev.\n" " use '-audio model=help' to show possible devices.\n", QEMU_ARCH_ALL) SRST -``-audio [driver=]driver[,model=value][,prop[=value][,...]]`` +``-audio [driver=]driver[,model=value][,prop=value[,...]]`` If the ``model`` option is specified, ``-audio`` is a shortcut for configuring both the guest audio hardware and the host audio backend in one go. The guest hardware model can be set with @@ -827,7 +827,7 @@ SRST ERST DEF("audiodev", HAS_ARG, QEMU_OPTION_audiodev, - "-audiodev [driver=]driver,id=id[,prop[=value][,...]]\n" + "-audiodev [driver=]driver,id=id[,prop=value[,...]]\n" " specifies the audio backend to use\n" " Use ``-audiodev help`` to list the available drivers\n" " id= identifier of the backend\n" @@ -840,25 +840,25 @@ DEF("audiodev", HAS_ARG, QEMU_OPTION_audiodev, " valid values: s8, s16, s32, u8, u16, u32, f32\n" " in|out.voices= number of voices to use\n" " in|out.buffer-length= length of buffer in microseconds\n" - "-audiodev none,id=id,[,prop[=value][,...]]\n" + "-audiodev none,id=id,[,prop=value[,...]]\n" " dummy driver that discards all output\n" #ifdef CONFIG_AUDIO_ALSA - "-audiodev alsa,id=id[,prop[=value][,...]]\n" + "-audiodev alsa,id=id[,prop=value[,...]]\n" " in|out.dev= name of the audio device to use\n" " in|out.period-length= length of period in microseconds\n" " in|out.try-poll= attempt to use poll mode\n" " threshold= threshold (in microseconds) when playback starts\n" #endif #ifdef CONFIG_AUDIO_COREAUDIO - "-audiodev coreaudio,id=id[,prop[=value][,...]]\n" + "-audiodev coreaudio,id=id[,prop=value[,...]]\n" " in|out.buffer-count= number of buffers\n" #endif #ifdef CONFIG_AUDIO_DSOUND - "-audiodev dsound,id=id[,prop[=value][,...]]\n" + "-audiodev dsound,id=id[,prop=value[,...]]\n" " latency= add extra latency to playback in microseconds\n" #endif #ifdef CONFIG_AUDIO_OSS - "-audiodev oss,id=id[,prop[=value][,...]]\n" + "-audiodev oss,id=id[,prop=value[,...]]\n" " in|out.dev= path of the audio device to use\n" " in|out.buffer-count= number of buffers\n" " in|out.try-poll= attempt to use poll mode\n" @@ -867,35 +867,35 @@ DEF("audiodev", HAS_ARG, QEMU_OPTION_audiodev, " dsp-policy= set timing policy (0..10), -1 to use fragment mode\n" #endif #ifdef CONFIG_AUDIO_PA - "-audiodev pa,id=id[,prop[=value][,...]]\n" + "-audiodev pa,id=id[,prop=value[,...]]\n" " server= PulseAudio server address\n" " in|out.name= source/sink device name\n" " in|out.latency= desired latency in microseconds\n" #endif #ifdef CONFIG_AUDIO_PIPEWIRE - "-audiodev pipewire,id=id[,prop[=value][,...]]\n" + "-audiodev pipewire,id=id[,prop=value[,...]]\n" " in|out.name= source/sink device name\n" " in|out.stream-name= name of pipewire stream\n" " in|out.latency= desired latency in microseconds\n" #endif #ifdef CONFIG_AUDIO_SDL - "-audiodev sdl,id=id[,prop[=value][,...]]\n" + "-audiodev sdl,id=id[,prop=value[,...]]\n" " in|out.buffer-count= number of buffers\n" #endif #ifdef CONFIG_AUDIO_SNDIO - "-audiodev sndio,id=id[,prop[=value][,...]]\n" + "-audiodev sndio,id=id[,prop=value[,...]]\n" #endif #ifdef CONFIG_SPICE - "-audiodev spice,id=id[,prop[=value][,...]]\n" + "-audiodev spice,id=id[,prop=value[,...]]\n" #endif #ifdef CONFIG_DBUS_DISPLAY - "-audiodev dbus,id=id[,prop[=value][,...]]\n" + "-audiodev dbus,id=id[,prop=value[,...]]\n" #endif - "-audiodev wav,id=id[,prop[=value][,...]]\n" + "-audiodev wav,id=id[,prop=value[,...]]\n" " path= path of wav file to record\n", QEMU_ARCH_ALL) SRST -``-audiodev [driver=]driver,id=id[,prop[=value][,...]]`` +``-audiodev [driver=]driver,id=id[,prop=value[,...]]`` Adds a new audio backend driver identified by id. There are global and driver specific properties. Some values can be set differently for input and output, they're marked with ``in|out.``. You can set @@ -954,11 +954,11 @@ SRST ``in|out.buffer-length=usecs`` Sets the size of the buffer in microseconds. -``-audiodev none,id=id[,prop[=value][,...]]`` +``-audiodev none,id=id[,prop=value[,...]]`` Creates a dummy backend that discards all outputs. This backend has no backend specific properties. -``-audiodev alsa,id=id[,prop[=value][,...]]`` +``-audiodev alsa,id=id[,prop=value[,...]]`` Creates backend using the ALSA. This backend is only available on Linux. @@ -977,7 +977,7 @@ SRST ``threshold=threshold`` Threshold (in microseconds) when playback starts. Default is 0. -``-audiodev coreaudio,id=id[,prop[=value][,...]]`` +``-audiodev coreaudio,id=id[,prop=value[,...]]`` Creates a backend using Apple's Core Audio. This backend is only available on Mac OS and only supports playback. @@ -986,7 +986,7 @@ SRST ``in|out.buffer-count=count`` Sets the count of the buffers. -``-audiodev dsound,id=id[,prop[=value][,...]]`` +``-audiodev dsound,id=id[,prop=value[,...]]`` Creates a backend using Microsoft's DirectSound. This backend is only available on Windows and only supports playback. @@ -996,7 +996,7 @@ SRST Add extra usecs microseconds latency to playback. Default is 10000 (10 ms). -``-audiodev oss,id=id[,prop[=value][,...]]`` +``-audiodev oss,id=id[,prop=value[,...]]`` Creates a backend using OSS. This backend is available on most Unix-like systems. @@ -1025,7 +1025,7 @@ SRST buffer sizes specified by ``buffer`` and ``buffer-count``. This option is ignored if you do not have OSS 4. Default is 5. -``-audiodev pa,id=id[,prop[=value][,...]]`` +``-audiodev pa,id=id[,prop=value[,...]]`` Creates a backend using PulseAudio. This backend is available on most systems. @@ -1041,7 +1041,7 @@ SRST Desired latency in microseconds. The PulseAudio server will try to honor this value but actual latencies may be lower or higher. -``-audiodev pipewire,id=id[,prop[=value][,...]]`` +``-audiodev pipewire,id=id[,prop=value[,...]]`` Creates a backend using PipeWire. This backend is available on most systems. @@ -1056,7 +1056,7 @@ SRST ``in|out.stream-name`` Specify the name of pipewire stream. -``-audiodev sdl,id=id[,prop[=value][,...]]`` +``-audiodev sdl,id=id[,prop=value[,...]]`` Creates a backend using SDL. This backend is available on most systems, but you should use your platform's native backend if possible. @@ -1066,7 +1066,7 @@ SRST ``in|out.buffer-count=count`` Sets the count of the buffers. -``-audiodev sndio,id=id[,prop[=value][,...]]`` +``-audiodev sndio,id=id[,prop=value[,...]]`` Creates a backend using SNDIO. This backend is available on OpenBSD and most other Unix-like systems. @@ -1079,13 +1079,13 @@ SRST ``in|out.latency=usecs`` Sets the desired period length in microseconds. -``-audiodev spice,id=id[,prop[=value][,...]]`` +``-audiodev spice,id=id[,prop=value[,...]]`` Creates a backend that sends audio through SPICE. This backend requires ``-spice`` and automatically selected in that case, so usually you can ignore this option. This backend has no backend specific properties. -``-audiodev wav,id=id[,prop[=value][,...]]`` +``-audiodev wav,id=id[,prop=value[,...]]`` Creates a backend that writes audio to a WAV file. Backend specific options are: @@ -1096,21 +1096,21 @@ SRST ERST DEF("device", HAS_ARG, QEMU_OPTION_device, - "-device driver[,prop[=value][,...]]\n" + "-device driver[,prop=value[,...]]\n" " add device (based on driver)\n" " prop=value,... sets driver properties\n" " use '-device help' to print all possible drivers\n" " use '-device driver,help' to print all possible properties\n", QEMU_ARCH_ALL) SRST -``-device driver[,prop[=value][,...]]`` +``-device driver[,prop=value[,...]]`` Add device driver. prop=value sets driver properties. Valid properties depend on the driver. To get help on possible drivers and properties, use ``-device help`` and ``-device driver,help``. Some drivers are: -``-device ipmi-bmc-sim,id=id[,prop[=value][,...]]`` +``-device ipmi-bmc-sim,id=id[,prop=value[,...]]`` Add an IPMI BMC. This is a simulation of a hardware management interface processor that normally sits on a system. It provides a watchdog and the ability to reset and power control the system. You @@ -2308,19 +2308,19 @@ DEF("spice", HAS_ARG, QEMU_OPTION_spice, " [,x509-dh-key-file=<file>][,addr=addr]\n" " [,ipv4=on|off][,ipv6=on|off][,unix=on|off]\n" " [,tls-ciphers=<list>]\n" - " [,tls-channel=[main|display|cursor|inputs|record|playback]]\n" - " [,plaintext-channel=[main|display|cursor|inputs|record|playback]]\n" + " [,tls-channel=main|display|cursor|inputs|record|playback]\n" + " [,plaintext-channel=main|display|cursor|inputs|record|playback]\n" " [,sasl=on|off][,disable-ticketing=on|off]\n" " [,password-secret=<secret-id>]\n" - " [,image-compression=[auto_glz|auto_lz|quic|glz|lz|off]]\n" - " [,jpeg-wan-compression=[auto|never|always]]\n" - " [,zlib-glz-wan-compression=[auto|never|always]]\n" - " [,streaming-video=[off|all|filter]][,disable-copy-paste=on|off]\n" - " [,disable-agent-file-xfer=on|off][,agent-mouse=[on|off]]\n" - " [,playback-compression=[on|off]][,seamless-migration=[on|off]]\n" + " [,image-compression=auto_glz|auto_lz|quic|glz|lz|off]\n" + " [,jpeg-wan-compression=auto|never|always]\n" + " [,zlib-glz-wan-compression=auto|never|always]\n" + " [,streaming-video=off|all|filter][,disable-copy-paste=on|off]\n" + " [,disable-agent-file-xfer=on|off][,agent-mouse=on|off]\n" + " [,playback-compression=on|off][,seamless-migration=on|off]\n" " [,video-codec=<codec>\n" " [,max-refresh-rate=rate\n" - " [,gl=[on|off]][,rendernode=<file>]\n" + " [,gl=on|off][,rendernode=<file>]\n" " enable spice\n" " at least one of {port, tls-port} is mandatory\n", QEMU_ARCH_ALL) @@ -2380,7 +2380,7 @@ SRST ``tls-ciphers=<list>`` Specify which ciphers to use. - ``tls-channel=[main|display|cursor|inputs|record|playback]``; \ ``plaintext-channel=[main|display|cursor|inputs|record|playback]`` + ``tls-channel=main|display|cursor|inputs|record|playback``; \ ``plaintext-channel=main|display|cursor|inputs|record|playback`` Force specific channel to be used with or without TLS encryption. The options can be specified multiple times to configure multiple channels. The special name "default" can be @@ -2388,24 +2388,24 @@ SRST explicitly forced into one mode the spice client is allowed to pick tls/plaintext as he pleases. - ``image-compression=[auto_glz|auto_lz|quic|glz|lz|off]`` + ``image-compression=auto_glz|auto_lz|quic|glz|lz|off`` Configure image compression (lossless). Default is auto\_glz. - ``jpeg-wan-compression=[auto|never|always]``; \ ``zlib-glz-wan-compression=[auto|never|always]`` + ``jpeg-wan-compression=auto|never|always``; \ ``zlib-glz-wan-compression=auto|never|always`` Configure wan image compression (lossy for slow links). Default is auto. - ``streaming-video=[off|all|filter]`` + ``streaming-video=off|all|filter`` Configure video stream detection. Default is off. - ``agent-mouse=[on|off]`` + ``agent-mouse=on|off`` Enable/disable passing mouse events via vdagent. Default is on. - ``playback-compression=[on|off]`` + ``playback-compression=on|off`` Enable/disable audio stream compression (using celt 0.5.1). Default is on. - ``seamless-migration=[on|off]`` + ``seamless-migration=on|off`` Enable/disable spice seamless migration. Default is off. ``video-codec=<codec>`` @@ -2419,7 +2419,7 @@ SRST Provide the maximum refresh rate (or FPS) at which the encoding requests should be sent to the Spice server. Default would be 30. - ``gl=[on|off]`` + ``gl=on|off`` Enable/disable OpenGL context. Default is off. ``rendernode=<file>`` @@ -2649,7 +2649,7 @@ SRST bandwidth when playing videos. Disabling adaptive encodings restores the original static behavior of encodings like Tight. - ``share=[allow-exclusive|force-shared|ignore]`` + ``share=allow-exclusive|force-shared|ignore`` Set display sharing policy. 'allow-exclusive' allows clients to ask for exclusive access. As suggested by the rfb spec this is implemented by dropping other connections. Connecting multiple @@ -4823,9 +4823,9 @@ SRST ERST DEF("mon", HAS_ARG, QEMU_OPTION_mon, \ - "-mon [chardev=]name[,mode=readline|control][,pretty[=on|off]]\n", QEMU_ARCH_ALL) + "-mon [chardev=]name[,mode=readline|control][,pretty=on|off]\n", QEMU_ARCH_ALL) SRST -``-mon [chardev=]name[,mode=readline|control][,pretty[=on|off]]`` +``-mon [chardev=]name[,mode=readline|control][,pretty=on|off]`` Set up a monitor connected to the chardev ``name``. QEMU supports two monitors: the Human Monitor Protocol (HMP; for human interaction), and the QEMU Monitor Protocol @@ -5514,14 +5514,14 @@ ERST #endif DEF("msg", HAS_ARG, QEMU_OPTION_msg, - "-msg [timestamp[=on|off]][,guest-name=[on|off]]\n" + "-msg [timestamp=on|off][,guest-name=on|off]\n" " control error message format\n" " timestamp=on enables timestamps (default: off)\n" " guest-name=on enables guest name prefix but only if\n" " -name guest option is set (default: off)\n", QEMU_ARCH_ALL) SRST -``-msg [timestamp[=on|off]][,guest-name[=on|off]]`` +``-msg [timestamp=on|off][,guest-name=on|off]`` Control error message format. ``timestamp=on|off`` -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
There are quite a few inappropriate uses of [...] around argument values. The [] are intended to indicate optionality, but in some cases it is used to wrap a set of enum values. In other cases it is being used to show the value is entirely optional, which was common behaviour for boolean values in the past. QEMU has deprecated short-form boolean options for quite a while though, and we should thus not advertize this possibility in the docs.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Reviewed-by: Markus Armbruster <armbru@redhat.com>
Functions marked with __attribute__((__constructor__)) will be invoked in linker order. In theory this is well defined, but in practice, it is hard to determine what this order will be with the layers of indirection through meson, ninja and the static libraries QEMU builds. Notably, the order currently appears different between Linux and Windows (as tested with Wine on Linux). This can cause problems when certain QEMU constructors have a dependancy on other QEMU constructors. To address this define a QEMU_CONSTRUCTOR_EARLY constant which provides a priority value that will run before other default constructors. This is to be used for QEMU constructors that are themselves self-contained, but may be relied upon by other constructors. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/compiler.h | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/include/qemu/compiler.h b/include/qemu/compiler.h index 1c2b673c05..4c49f52eb0 100644 --- a/include/qemu/compiler.h +++ b/include/qemu/compiler.h @@ -194,6 +194,14 @@ # define QEMU_USED #endif +/* + * A priority for __attribute__((constructor(...))) that + * will run earlier than the default constructors. Must + * only be used for functions that have no dependency + * on global initialization of other QEMU subsystems. + */ +#define QEMU_CONSTRUCTOR_EARLY 101 + /* * Disable -ftrivial-auto-var-init on a local variable. * -- 2.52.0
On 1/8/26 18:03, Daniel P. Berrangé wrote:
Functions marked with __attribute__((__constructor__)) will be invoked in linker order. In theory this is well defined, but in practice, it is hard to determine what this order will be with the layers of indirection through meson, ninja and the static libraries QEMU builds.
Notably, the order currently appears different between Linux and Windows (as tested with Wine on Linux). This can cause problems when certain QEMU constructors have a dependancy on other QEMU constructors.
What dependency are you seeing, or introducing? In theory QEMU constructors should not have any dependency, as we only use them to initialize static data structures (such as the various *_init macros). Not an objection, but I'd like to understand this better. Paolo
To address this define a QEMU_CONSTRUCTOR_EARLY constant which provides a priority value that will run before other default constructors. This is to be used for QEMU constructors that are themselves self-contained, but may be relied upon by other constructors.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/compiler.h | 8 ++++++++ 1 file changed, 8 insertions(+)
diff --git a/include/qemu/compiler.h b/include/qemu/compiler.h index 1c2b673c05..4c49f52eb0 100644 --- a/include/qemu/compiler.h +++ b/include/qemu/compiler.h @@ -194,6 +194,14 @@ # define QEMU_USED #endif
+/* + * A priority for __attribute__((constructor(...))) that + * will run earlier than the default constructors. Must + * only be used for functions that have no dependency + * on global initialization of other QEMU subsystems. + */ +#define QEMU_CONSTRUCTOR_EARLY 101 + /* * Disable -ftrivial-auto-var-init on a local variable. *
On Fri, Jan 09, 2026 at 12:39:59PM +0100, Paolo Bonzini wrote:
On 1/8/26 18:03, Daniel P. Berrangé wrote:
Functions marked with __attribute__((__constructor__)) will be invoked in linker order. In theory this is well defined, but in practice, it is hard to determine what this order will be with the layers of indirection through meson, ninja and the static libraries QEMU builds.
Notably, the order currently appears different between Linux and Windows (as tested with Wine on Linux). This can cause problems when certain QEMU constructors have a dependancy on other QEMU constructors.
What dependency are you seeing, or introducing?
In theory QEMU constructors should not have any dependency, as we only use them to initialize static data structures (such as the various *_init macros).
Not an objection, but I'd like to understand this better.
See the commit message in patch 2. Essentially the RCU thread gets spawned from a constructor, and if anything it does results in an error_report() call, it will trigger use of monitor APIs before the monitor constructor has had a chance to run. IMHO the root problem is that it is pretty dubious for us to be spawning the RCU thread from a constructor. Constructors should be limited to minimal initialization of state. Spawning threads is outside the boundary of what I'd consider reasonable for a constructor todo. I didn't want try to tackle refactoring the RCU thread creation though, hence this gross workaround.
Paolo
To address this define a QEMU_CONSTRUCTOR_EARLY constant which provides a priority value that will run before other default constructors. This is to be used for QEMU constructors that are themselves self-contained, but may be relied upon by other constructors.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/compiler.h | 8 ++++++++ 1 file changed, 8 insertions(+)
diff --git a/include/qemu/compiler.h b/include/qemu/compiler.h index 1c2b673c05..4c49f52eb0 100644 --- a/include/qemu/compiler.h +++ b/include/qemu/compiler.h @@ -194,6 +194,14 @@ # define QEMU_USED #endif +/* + * A priority for __attribute__((constructor(...))) that + * will run earlier than the default constructors. Must + * only be used for functions that have no dependency + * on global initialization of other QEMU subsystems. + */ +#define QEMU_CONSTRUCTOR_EARLY 101 + /* * Disable -ftrivial-auto-var-init on a local variable. *
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 :|
On 1/9/26 12:46, Daniel P. Berrangé wrote:
IMHO the root problem is that it is pretty dubious for us to be spawning the RCU thread from a constructor. Constructors should be limited to minimal initialization of state. Spawning threads is outside the boundary of what I'd consider reasonable for a constructor todo. I didn't want try to tackle refactoring the RCU thread creation though, hence this gross workaround.
I see. Maybe we could (just as gross but smaller) do the RCU constructor late. Not something that you need to do now, of course. Paolo
Paolo Bonzini <pbonzini@redhat.com> writes:
On 1/9/26 12:46, Daniel P. Berrangé wrote:
IMHO the root problem is that it is pretty dubious for us to be spawning the RCU thread from a constructor. Constructors should be limited to minimal initialization of state.
Yes! Discussed in review of v3: https://lore.kernel.org/qemu-devel/87frck1dds.fsf@pond.sub.org/ Message-ID: <87frck1dds.fsf@pond.sub.org>
Spawning threads is outside the boundary of what I'd consider reasonable for a constructor todo. I didn't want try to tackle refactoring the RCU thread creation though, hence this gross workaround.
I see. Maybe we could (just as gross but smaller) do the RCU constructor late. Not something that you need to do now, of course.
Could we use an old-fashioned initialization function instead of a constructor for RCU?
Il mar 13 gen 2026, 10:04 Markus Armbruster <armbru@redhat.com> ha scritto:
Paolo Bonzini <pbonzini@redhat.com> writes:
On 1/9/26 12:46, Daniel P. Berrangé wrote:
IMHO the root problem is that it is pretty dubious for us to be spawning the RCU thread from a constructor. Constructors should be limited to minimal initialization of state.
Yes! Discussed in review of v3:
https://lore.kernel.org/qemu-devel/87frck1dds.fsf@pond.sub.org/ Message-ID: <87frck1dds.fsf@pond.sub.org>
Spawning threads is outside the boundary of what I'd consider reasonable for a constructor todo. I didn't want try to tackle refactoring the RCU thread creation though, hence this gross workaround.
I see. Maybe we could (just as gross but smaller) do the RCU constructor late. Not something that you need to do now, of course.
Could we use an old-fashioned initialization function instead of a constructor for RCU?
You have to do it in all main()s, which make it unwieldy for tests etc. Another possibility is to do it lazily on first call_rcu, and just clear the flag in the atfork callbacks. Paolo
On Tue, Jan 13, 2026 at 10:32:48AM +0100, Paolo Bonzini wrote:
Il mar 13 gen 2026, 10:04 Markus Armbruster <armbru@redhat.com> ha scritto:
Paolo Bonzini <pbonzini@redhat.com> writes:
On 1/9/26 12:46, Daniel P. Berrangé wrote:
IMHO the root problem is that it is pretty dubious for us to be spawning the RCU thread from a constructor. Constructors should be limited to minimal initialization of state.
Yes! Discussed in review of v3:
https://lore.kernel.org/qemu-devel/87frck1dds.fsf@pond.sub.org/ Message-ID: <87frck1dds.fsf@pond.sub.org>
Spawning threads is outside the boundary of what I'd consider reasonable for a constructor todo. I didn't want try to tackle refactoring the RCU thread creation though, hence this gross workaround.
I see. Maybe we could (just as gross but smaller) do the RCU constructor late. Not something that you need to do now, of course.
Could we use an old-fashioned initialization function instead of a constructor for RCU?
You have to do it in all main()s, which make it unwieldy for tests etc.
Another possibility is to do it lazily on first call_rcu, and just clear the flag in the atfork callbacks.
I'd be concerned that we would not be able to rationalize what thread is starting the RCU thread. It will probably be the main thread, but proving that will be difficult. A thread which is not the main thread may have undesirable CPU affinity set which we don't have the RCU thread to inherit. IMHO if we remove the constructor, then we need to have a strong guarantee that it is spawned from the main() method and not from any other background thread. I wouldn't rule our doing it manually from every main() method. We could probably come up with something to make it less of a burden for test programs. eg replace g_test_init() with q_test_init() which combines g_test_init with RCU thread creation. 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 :|
Some monitor functions, most notably, monitor_cur() rely on global data being initialized by 'monitor_init_globals()'. The latter is called relatively late in startup. If code triggers error_report() before monitor_init_globals() is called, QEMU will abort when accessing the uninitialized monitor mutex. The critical monitor global data must be initialized from a constructor function, to improve the guarantee that it is done before any possible calls to monitor_cur(). Not only that, but the constructor must be marked to run before the default constructor in case any of them trigger error reporting. Note in particular that the RCU constructor will spawn a background thread so we might even have non-constructor QEMU code running concurrently with other constructors. As a general note, constructors should be extrememly careful about what QEMU code they invoke, as it cannot be guaranteed that the process is fully initialized and so not all normal QEMU API rules apply. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Markus Armbruster <armbru@redhat.com> Fixes: e69ee454b5f9 (monitor: Make current monitor a per-coroutine property) Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- monitor/monitor.c | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/monitor/monitor.c b/monitor/monitor.c index 1273eb7260..dd2c45ded0 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -708,18 +708,22 @@ void monitor_cleanup(void) } } -static void monitor_qapi_event_init(void) +/* + * Initialize static vars that have no deps on external + * module initialization, and are required for external + * functions to call things like monitor_cur() + */ +static void __attribute__((__constructor__(QEMU_CONSTRUCTOR_EARLY))) +monitor_init_static(void) { + qemu_mutex_init(&monitor_lock); + coroutine_mon = g_hash_table_new(NULL, NULL); monitor_qapi_event_state = g_hash_table_new(qapi_event_throttle_hash, qapi_event_throttle_equal); } void monitor_init_globals(void) { - monitor_qapi_event_init(); - qemu_mutex_init(&monitor_lock); - coroutine_mon = g_hash_table_new(NULL, NULL); - /* * The dispatcher BH must run in the main loop thread, since we * have commands assuming that context. It would be nice to get -- 2.52.0
When thread naming was introduced years ago, it was disabled by default and put behind a command line flag: commit 8f480de0c91a18d550721f8d9af969ebfbda0793 Author: Dr. David Alan Gilbert <dgilbert@redhat.com> Date: Thu Jan 30 10:20:31 2014 +0000 Add 'debug-threads' suboption to --name This was done based on a concern that something might depend on the historical thread naming. Thread names, however, were never promised to be part of QEMU's public API. The defaults will vary across platforms, so no assumptions should ever be made about naming. An opt-in behaviour is also unfortunately incompatible with RCU which creates its thread from an constructor function which is run before command line args are parsed. Thus the RCU thread lacks any name. libvirt has unconditionally enabled debug-threads=yes on all VMs it creates for 10 years. Interestingly this DID expose a bug in libvirt, as it parsed /proc/$PID/stat and could not cope with a space in the thread name. This was a latent pre-existing bug in libvirt though, and not a part of QEMU's API. Having thread names always available, will allow thread names to be included in error reports and log messags QEMU prints by default, which will improve ability to triage QEMU bugs. Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- docs/about/deprecated.rst | 7 +++++++ include/qemu/thread.h | 1 - system/vl.c | 12 +++++++----- util/qemu-thread-posix.c | 18 +----------------- util/qemu-thread-win32.c | 27 ++++++--------------------- 5 files changed, 21 insertions(+), 44 deletions(-) diff --git a/docs/about/deprecated.rst b/docs/about/deprecated.rst index 7abb3dab59..d1acefe9d2 100644 --- a/docs/about/deprecated.rst +++ b/docs/about/deprecated.rst @@ -54,6 +54,13 @@ as short-form boolean values, and passed to plugins as ``arg_name=on``. However, short-form booleans are deprecated and full explicit ``arg_name=on`` form is preferred. +``debug-threads`` option for ``-name`` (since 11.0) +''''''''''''''''''''''''''''''''''''''''''''''''''' + +The ``debug-threads`` option of the ``-name`` argument is now +ignored. Thread naming is unconditionally enabled for all platforms +where it is supported. + QEMU Machine Protocol (QMP) commands ------------------------------------ diff --git a/include/qemu/thread.h b/include/qemu/thread.h index f0302ed01f..3a286bb3ef 100644 --- a/include/qemu/thread.h +++ b/include/qemu/thread.h @@ -215,7 +215,6 @@ void *qemu_thread_join(QemuThread *thread); void qemu_thread_get_self(QemuThread *thread); bool qemu_thread_is_self(QemuThread *thread); G_NORETURN void qemu_thread_exit(void *retval); -void qemu_thread_naming(bool enable); struct Notifier; /** diff --git a/system/vl.c b/system/vl.c index b60b883050..60bdd58548 100644 --- a/system/vl.c +++ b/system/vl.c @@ -403,9 +403,8 @@ static QemuOptsList qemu_name_opts = { }, { .name = "debug-threads", .type = QEMU_OPT_BOOL, - .help = "When enabled, name the individual threads; defaults off.\n" - "NOTE: The thread names are for debugging and not a\n" - "stable API.", + .help = "Enable thread names" + "(deprecated, always enabled where supported)", }, { /* End of list */ } }, @@ -554,9 +553,12 @@ static int parse_name(void *opaque, QemuOpts *opts, Error **errp) { const char *proc_name; - if (qemu_opt_get(opts, "debug-threads")) { - qemu_thread_naming(qemu_opt_get_bool(opts, "debug-threads", false)); + if (qemu_opt_get(opts, "debug-threads") && + !qemu_opt_get_bool(opts, "debug-threads", false)) { + fprintf(stderr, "Ignoring deprecated 'debug-threads=no' option, " \ + "thread naming is unconditionally enabled\n"); } + qemu_name = qemu_opt_get(opts, "guest"); proc_name = qemu_opt_get(opts, "process"); diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index ba725444ba..7c985b5d38 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -22,22 +22,6 @@ #include <pthread_np.h> #endif -static bool name_threads; - -void qemu_thread_naming(bool enable) -{ - name_threads = enable; - -#if !defined CONFIG_PTHREAD_SETNAME_NP_W_TID && \ - !defined CONFIG_PTHREAD_SETNAME_NP_WO_TID && \ - !defined CONFIG_PTHREAD_SET_NAME_NP - /* This is a debugging option, not fatal */ - if (enable) { - fprintf(stderr, "qemu: thread naming not supported on this host\n"); - } -#endif -} - static void error_exit(int err, const char *msg) { fprintf(stderr, "qemu: %s: %s\n", msg, strerror(err)); @@ -361,7 +345,7 @@ static void *qemu_thread_start(void *args) /* Attempt to set the threads name; note that this is for debug, so * we're not going to fail if we can't set it. */ - if (name_threads && qemu_thread_args->name) { + if (qemu_thread_args->name) { # if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) pthread_setname_np(pthread_self(), qemu_thread_args->name); # elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index ca2e0b512e..9595a5b090 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -17,8 +17,6 @@ #include "qemu-thread-common.h" #include <process.h> -static bool name_threads; - typedef HRESULT (WINAPI *pSetThreadDescription) (HANDLE hThread, PCWSTR lpThreadDescription); static pSetThreadDescription SetThreadDescriptionFunc; @@ -44,16 +42,6 @@ static bool load_set_thread_description(void) return !!SetThreadDescriptionFunc; } -void qemu_thread_naming(bool enable) -{ - name_threads = enable; - - if (enable && !load_set_thread_description()) { - fprintf(stderr, "qemu: thread naming not supported on this host\n"); - name_threads = false; - } -} - static void error_exit(int err, const char *msg) { char *pstr; @@ -328,23 +316,20 @@ void *qemu_thread_join(QemuThread *thread) return ret; } -static bool set_thread_description(HANDLE h, const char *name) +static void set_thread_description(HANDLE h, const char *name) { - HRESULT hr; g_autofree wchar_t *namew = NULL; if (!load_set_thread_description()) { - return false; + return; } namew = g_utf8_to_utf16(name, -1, NULL, NULL, NULL); if (!namew) { - return false; + return; } - hr = SetThreadDescriptionFunc(h, namew); - - return SUCCEEDED(hr); + SetThreadDescriptionFunc(h, namew); } void qemu_thread_create(QemuThread *thread, const char *name, @@ -370,8 +355,8 @@ void qemu_thread_create(QemuThread *thread, const char *name, if (!hThread) { error_exit(GetLastError(), __func__); } - if (name_threads && name && !set_thread_description(hThread, name)) { - fprintf(stderr, "qemu: failed to set thread description: %s\n", name); + if (name) { + set_thread_description(hThread, name); } CloseHandle(hThread); -- 2.52.0
The ability to set the thread name needs to be used in a number of places, so expose the current impls as public methods. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + util/qemu-thread-posix.c | 26 ++++++++++++++++---------- util/qemu-thread-win32.c | 13 ++++++++----- 3 files changed, 25 insertions(+), 15 deletions(-) diff --git a/include/qemu/thread.h b/include/qemu/thread.h index 3a286bb3ef..27b888ab0a 100644 --- a/include/qemu/thread.h +++ b/include/qemu/thread.h @@ -215,6 +215,7 @@ void *qemu_thread_join(QemuThread *thread); void qemu_thread_get_self(QemuThread *thread); bool qemu_thread_is_self(QemuThread *thread); G_NORETURN void qemu_thread_exit(void *retval); +void qemu_thread_set_name(const char *name); struct Notifier; /** diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index 7c985b5d38..b1c127dbe3 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -329,6 +329,21 @@ static void qemu_thread_atexit_notify(void *arg) notifier_list_notify(&thread_exit, NULL); } +void qemu_thread_set_name(const char *name) +{ + /* + * Attempt to set the threads name; note that this is for debug, so + * we're not going to fail if we can't set it. + */ +# if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) + pthread_setname_np(pthread_self(), name); +# elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) + pthread_setname_np(name); +# elif defined(CONFIG_PTHREAD_SET_NAME_NP) + pthread_set_name_np(pthread_self(), name); +# endif +} + typedef struct { void *(*start_routine)(void *); void *arg; @@ -342,17 +357,8 @@ static void *qemu_thread_start(void *args) void *arg = qemu_thread_args->arg; void *r; - /* Attempt to set the threads name; note that this is for debug, so - * we're not going to fail if we can't set it. - */ if (qemu_thread_args->name) { -# if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) - pthread_setname_np(pthread_self(), qemu_thread_args->name); -# elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) - pthread_setname_np(qemu_thread_args->name); -# elif defined(CONFIG_PTHREAD_SET_NAME_NP) - pthread_set_name_np(pthread_self(), qemu_thread_args->name); -# endif + qemu_thread_set_name(qemu_thread_args->name); } QEMU_TSAN_ANNOTATE_THREAD_NAME(qemu_thread_args->name); g_free(qemu_thread_args->name); diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 9595a5b090..4d2d663a9a 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -225,6 +225,7 @@ struct QemuThreadData { void *arg; short mode; NotifierList exit; + char *name; /* Only used for joinable threads. */ bool exited; @@ -266,6 +267,10 @@ static unsigned __stdcall win32_start_routine(void *arg) void *(*start_routine)(void *) = data->start_routine; void *thread_arg = data->arg; + if (data->name) { + qemu_thread_set_name(data->name); + g_clear_pointer(&data->name, g_free); + } qemu_thread_data = data; qemu_thread_exit(start_routine(thread_arg)); abort(); @@ -316,7 +321,7 @@ void *qemu_thread_join(QemuThread *thread) return ret; } -static void set_thread_description(HANDLE h, const char *name) +void qemu_thread_set_name(const char *name) { g_autofree wchar_t *namew = NULL; @@ -329,7 +334,7 @@ static void set_thread_description(HANDLE h, const char *name) return; } - SetThreadDescriptionFunc(h, namew); + SetThreadDescriptionFunc(GetCurrentThread(), namew); } void qemu_thread_create(QemuThread *thread, const char *name, @@ -344,6 +349,7 @@ void qemu_thread_create(QemuThread *thread, const char *name, data->arg = arg; data->mode = mode; data->exited = false; + data->name = g_strdup(name); notifier_list_init(&data->exit); if (data->mode != QEMU_THREAD_DETACHED) { @@ -355,9 +361,6 @@ void qemu_thread_create(QemuThread *thread, const char *name, if (!hThread) { error_exit(GetLastError(), __func__); } - if (name) { - set_thread_description(hThread, name); - } CloseHandle(hThread); thread->data = data; -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
The ability to set the thread name needs to be used in a number of places, so expose the current impls as public methods.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + util/qemu-thread-posix.c | 26 ++++++++++++++++---------- util/qemu-thread-win32.c | 13 ++++++++----- 3 files changed, 25 insertions(+), 15 deletions(-)
diff --git a/include/qemu/thread.h b/include/qemu/thread.h index 3a286bb3ef..27b888ab0a 100644 --- a/include/qemu/thread.h +++ b/include/qemu/thread.h @@ -215,6 +215,7 @@ void *qemu_thread_join(QemuThread *thread); void qemu_thread_get_self(QemuThread *thread); bool qemu_thread_is_self(QemuThread *thread); G_NORETURN void qemu_thread_exit(void *retval); +void qemu_thread_set_name(const char *name);
struct Notifier; /** diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index 7c985b5d38..b1c127dbe3 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -329,6 +329,21 @@ static void qemu_thread_atexit_notify(void *arg) notifier_list_notify(&thread_exit, NULL); }
+void qemu_thread_set_name(const char *name) +{ + /* + * Attempt to set the threads name; note that this is for debug, so + * we're not going to fail if we can't set it. + */ +# if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) + pthread_setname_np(pthread_self(), name); +# elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) + pthread_setname_np(name); +# elif defined(CONFIG_PTHREAD_SET_NAME_NP) + pthread_set_name_np(pthread_self(), name); +# endif +} + typedef struct { void *(*start_routine)(void *); void *arg; @@ -342,17 +357,8 @@ static void *qemu_thread_start(void *args) void *arg = qemu_thread_args->arg; void *r;
- /* Attempt to set the threads name; note that this is for debug, so - * we're not going to fail if we can't set it. - */ if (qemu_thread_args->name) { -# if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) - pthread_setname_np(pthread_self(), qemu_thread_args->name); -# elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) - pthread_setname_np(qemu_thread_args->name); -# elif defined(CONFIG_PTHREAD_SET_NAME_NP) - pthread_set_name_np(pthread_self(), qemu_thread_args->name); -# endif + qemu_thread_set_name(qemu_thread_args->name); } QEMU_TSAN_ANNOTATE_THREAD_NAME(qemu_thread_args->name); g_free(qemu_thread_args->name);
qemu_thread_set_name() is factored out. No change in behavior.
diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 9595a5b090..4d2d663a9a 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -225,6 +225,7 @@ struct QemuThreadData { void *arg; short mode; NotifierList exit; + char *name;
/* Only used for joinable threads. */ bool exited; @@ -266,6 +267,10 @@ static unsigned __stdcall win32_start_routine(void *arg) void *(*start_routine)(void *) = data->start_routine; void *thread_arg = data->arg;
+ if (data->name) { + qemu_thread_set_name(data->name); + g_clear_pointer(&data->name, g_free); + } qemu_thread_data = data; qemu_thread_exit(start_routine(thread_arg)); abort(); @@ -316,7 +321,7 @@ void *qemu_thread_join(QemuThread *thread) return ret; }
-static void set_thread_description(HANDLE h, const char *name) +void qemu_thread_set_name(const char *name) { g_autofree wchar_t *namew = NULL;
@@ -329,7 +334,7 @@ static void set_thread_description(HANDLE h, const char *name) return; }
- SetThreadDescriptionFunc(h, namew); + SetThreadDescriptionFunc(GetCurrentThread(), namew); }
void qemu_thread_create(QemuThread *thread, const char *name, @@ -344,6 +349,7 @@ void qemu_thread_create(QemuThread *thread, const char *name, data->arg = arg; data->mode = mode; data->exited = false; + data->name = g_strdup(name); notifier_list_init(&data->exit);
if (data->mode != QEMU_THREAD_DETACHED) { @@ -355,9 +361,6 @@ void qemu_thread_create(QemuThread *thread, const char *name, if (!hThread) { error_exit(GetLastError(), __func__); } - if (name) { - set_thread_description(hThread, name); - } CloseHandle(hThread);
thread->data = data;
This delays setting the thread name until the thread runs. Fine, I guess, but I'd mention it in the commit message. The new QemuThreadData member @name is non-null only between thread creation and thread name setting, unlike the other members under /* Passed to win32_start_routine. */ Worth a comment? Keep it alive until the thread dies? Entirely up to you. Reviewed-by: Markus Armbruster <armbru@redhat.com>
On Tue, Jan 13, 2026 at 10:16:06AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
The ability to set the thread name needs to be used in a number of places, so expose the current impls as public methods.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + util/qemu-thread-posix.c | 26 ++++++++++++++++---------- util/qemu-thread-win32.c | 13 ++++++++----- 3 files changed, 25 insertions(+), 15 deletions(-)
diff --git a/include/qemu/thread.h b/include/qemu/thread.h index 3a286bb3ef..27b888ab0a 100644 --- a/include/qemu/thread.h +++ b/include/qemu/thread.h @@ -215,6 +215,7 @@ void *qemu_thread_join(QemuThread *thread); void qemu_thread_get_self(QemuThread *thread); bool qemu_thread_is_self(QemuThread *thread); G_NORETURN void qemu_thread_exit(void *retval); +void qemu_thread_set_name(const char *name);
struct Notifier; /** diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index 7c985b5d38..b1c127dbe3 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -329,6 +329,21 @@ static void qemu_thread_atexit_notify(void *arg) notifier_list_notify(&thread_exit, NULL); }
+void qemu_thread_set_name(const char *name) +{ + /* + * Attempt to set the threads name; note that this is for debug, so + * we're not going to fail if we can't set it. + */ +# if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) + pthread_setname_np(pthread_self(), name); +# elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) + pthread_setname_np(name); +# elif defined(CONFIG_PTHREAD_SET_NAME_NP) + pthread_set_name_np(pthread_self(), name); +# endif +} + typedef struct { void *(*start_routine)(void *); void *arg; @@ -342,17 +357,8 @@ static void *qemu_thread_start(void *args) void *arg = qemu_thread_args->arg; void *r;
- /* Attempt to set the threads name; note that this is for debug, so - * we're not going to fail if we can't set it. - */ if (qemu_thread_args->name) { -# if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) - pthread_setname_np(pthread_self(), qemu_thread_args->name); -# elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) - pthread_setname_np(qemu_thread_args->name); -# elif defined(CONFIG_PTHREAD_SET_NAME_NP) - pthread_set_name_np(pthread_self(), qemu_thread_args->name); -# endif + qemu_thread_set_name(qemu_thread_args->name); } QEMU_TSAN_ANNOTATE_THREAD_NAME(qemu_thread_args->name); g_free(qemu_thread_args->name);
qemu_thread_set_name() is factored out. No change in behavior.
diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 9595a5b090..4d2d663a9a 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -225,6 +225,7 @@ struct QemuThreadData { void *arg; short mode; NotifierList exit; + char *name;
/* Only used for joinable threads. */ bool exited; @@ -266,6 +267,10 @@ static unsigned __stdcall win32_start_routine(void *arg) void *(*start_routine)(void *) = data->start_routine; void *thread_arg = data->arg;
+ if (data->name) { + qemu_thread_set_name(data->name); + g_clear_pointer(&data->name, g_free); + } qemu_thread_data = data; qemu_thread_exit(start_routine(thread_arg)); abort(); @@ -316,7 +321,7 @@ void *qemu_thread_join(QemuThread *thread) return ret; }
-static void set_thread_description(HANDLE h, const char *name) +void qemu_thread_set_name(const char *name) { g_autofree wchar_t *namew = NULL;
@@ -329,7 +334,7 @@ static void set_thread_description(HANDLE h, const char *name) return; }
- SetThreadDescriptionFunc(h, namew); + SetThreadDescriptionFunc(GetCurrentThread(), namew); }
void qemu_thread_create(QemuThread *thread, const char *name, @@ -344,6 +349,7 @@ void qemu_thread_create(QemuThread *thread, const char *name, data->arg = arg; data->mode = mode; data->exited = false; + data->name = g_strdup(name); notifier_list_init(&data->exit);
if (data->mode != QEMU_THREAD_DETACHED) { @@ -355,9 +361,6 @@ void qemu_thread_create(QemuThread *thread, const char *name, if (!hThread) { error_exit(GetLastError(), __func__); } - if (name) { - set_thread_description(hThread, name); - } CloseHandle(hThread);
thread->data = data;
This delays setting the thread name until the thread runs. Fine, I guess, but I'd mention it in the commit message.
The new QemuThreadData member @name is non-null only between thread creation and thread name setting, unlike the other members under /* Passed to win32_start_routine. */ Worth a comment? Keep it alive until the thread dies? Entirely up to you.
win32_start_routine never returns as it calls into qemu_thread_exit so it is simpler to just free immediately after use. I'll comment the struct.
Reviewed-by: Markus Armbruster <armbru@redhat.com>
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 :|
On Tue, Jan 13, 2026 at 10:16:06AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
The ability to set the thread name needs to be used in a number of places, so expose the current impls as public methods.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + util/qemu-thread-posix.c | 26 ++++++++++++++++---------- util/qemu-thread-win32.c | 13 ++++++++----- 3 files changed, 25 insertions(+), 15 deletions(-)
diff --git a/include/qemu/thread.h b/include/qemu/thread.h index 3a286bb3ef..27b888ab0a 100644 --- a/include/qemu/thread.h +++ b/include/qemu/thread.h @@ -215,6 +215,7 @@ void *qemu_thread_join(QemuThread *thread); void qemu_thread_get_self(QemuThread *thread); bool qemu_thread_is_self(QemuThread *thread); G_NORETURN void qemu_thread_exit(void *retval); +void qemu_thread_set_name(const char *name);
struct Notifier; /** diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index 7c985b5d38..b1c127dbe3 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -329,6 +329,21 @@ static void qemu_thread_atexit_notify(void *arg) notifier_list_notify(&thread_exit, NULL); }
+void qemu_thread_set_name(const char *name) +{ + /* + * Attempt to set the threads name; note that this is for debug, so + * we're not going to fail if we can't set it. + */ +# if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) + pthread_setname_np(pthread_self(), name); +# elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) + pthread_setname_np(name); +# elif defined(CONFIG_PTHREAD_SET_NAME_NP) + pthread_set_name_np(pthread_self(), name); +# endif +} + typedef struct { void *(*start_routine)(void *); void *arg; @@ -342,17 +357,8 @@ static void *qemu_thread_start(void *args) void *arg = qemu_thread_args->arg; void *r;
- /* Attempt to set the threads name; note that this is for debug, so - * we're not going to fail if we can't set it. - */ if (qemu_thread_args->name) { -# if defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) - pthread_setname_np(pthread_self(), qemu_thread_args->name); -# elif defined(CONFIG_PTHREAD_SETNAME_NP_WO_TID) - pthread_setname_np(qemu_thread_args->name); -# elif defined(CONFIG_PTHREAD_SET_NAME_NP) - pthread_set_name_np(pthread_self(), qemu_thread_args->name); -# endif + qemu_thread_set_name(qemu_thread_args->name); } QEMU_TSAN_ANNOTATE_THREAD_NAME(qemu_thread_args->name); g_free(qemu_thread_args->name);
qemu_thread_set_name() is factored out. No change in behavior.
diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 9595a5b090..4d2d663a9a 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -225,6 +225,7 @@ struct QemuThreadData { void *arg; short mode; NotifierList exit; + char *name;
/* Only used for joinable threads. */ bool exited; @@ -266,6 +267,10 @@ static unsigned __stdcall win32_start_routine(void *arg) void *(*start_routine)(void *) = data->start_routine; void *thread_arg = data->arg;
+ if (data->name) { + qemu_thread_set_name(data->name); + g_clear_pointer(&data->name, g_free); + } qemu_thread_data = data; qemu_thread_exit(start_routine(thread_arg)); abort(); @@ -316,7 +321,7 @@ void *qemu_thread_join(QemuThread *thread) return ret; }
-static void set_thread_description(HANDLE h, const char *name) +void qemu_thread_set_name(const char *name) { g_autofree wchar_t *namew = NULL;
@@ -329,7 +334,7 @@ static void set_thread_description(HANDLE h, const char *name) return; }
- SetThreadDescriptionFunc(h, namew); + SetThreadDescriptionFunc(GetCurrentThread(), namew); }
void qemu_thread_create(QemuThread *thread, const char *name, @@ -344,6 +349,7 @@ void qemu_thread_create(QemuThread *thread, const char *name, data->arg = arg; data->mode = mode; data->exited = false; + data->name = g_strdup(name); notifier_list_init(&data->exit);
if (data->mode != QEMU_THREAD_DETACHED) { @@ -355,9 +361,6 @@ void qemu_thread_create(QemuThread *thread, const char *name, if (!hThread) { error_exit(GetLastError(), __func__); } - if (name) { - set_thread_description(hThread, name); - } CloseHandle(hThread);
thread->data = data;
This delays setting the thread name until the thread runs. Fine, I guess, but I'd mention it in the commit message.
Returning to this, the change is arguably /not/ delaying setting the thread name, but in fact fixing a race condition when settnig the thread name. This existing 'set_thread_description' call is taking place in the parent thread, and at this point in the time the child thread has potentially already been scheduled to run. So if the parent thread was unscheduled, it is possible the child was running without having it name set. This change eliminates that race. This distinction is important enough that I think I'll move this specific change out into its own self-contained commit.
The new QemuThreadData member @name is non-null only between thread creation and thread name setting, unlike the other members under /* Passed to win32_start_routine. */ Worth a comment? Keep it alive until the thread dies? Entirely up to you.
Reviewed-by: Markus Armbruster <armbru@redhat.com>
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 :|
Daniel P. Berrangé <berrange@redhat.com> writes:
On Tue, Jan 13, 2026 at 10:16:06AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
The ability to set the thread name needs to be used in a number of places, so expose the current impls as public methods.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
[...]
This delays setting the thread name until the thread runs. Fine, I guess, but I'd mention it in the commit message.
Returning to this, the change is arguably /not/ delaying setting the thread name, but in fact fixing a race condition when settnig the thread name.
This existing 'set_thread_description' call is taking place in the parent thread, and at this point in the time the child thread has potentially already been scheduled to run. So if the parent thread was unscheduled, it is possible the child was running without having it name set. This change eliminates that race.
This distinction is important enough that I think I'll move this specific change out into its own self-contained commit.
Makes sense, thanks! [...]
This has greater portability than directly call pthread_setname_np, which is only 1 out of 3 possible functions for pthreads that can set the name. The new API requires a trampoline function, since it can only set the name of the current thread. Reviewed-by: Christian Schoenebeck <qemu_oss@crudebyte.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- audio/jackaudio.c | 30 ++++++++++++++++++++++++------ 1 file changed, 24 insertions(+), 6 deletions(-) diff --git a/audio/jackaudio.c b/audio/jackaudio.c index 7a3fcaedba..c47a1a3781 100644 --- a/audio/jackaudio.c +++ b/audio/jackaudio.c @@ -629,18 +629,36 @@ static void qjack_enable_in(HWVoiceIn *hw, bool enable) ji->c.enabled = enable; } -#if !defined(WIN32) && defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) +#if !defined(WIN32) +struct QJackThreadData { + void *(*function)(void *); + void *arg; +}; + +static void *qjack_thread_trampoline(void *targ) +{ + struct QJackThreadData *data = targ; + void *(*function)(void *) = data->function; + void *arg = data->arg; + + g_free(data); + qemu_thread_set_name("jack-client"); + + return function(arg); +} + static int qjack_thread_creator(jack_native_thread_t *thread, const pthread_attr_t *attr, void *(*function)(void *), void *arg) { - int ret = pthread_create(thread, attr, function, arg); + struct QJackThreadData *data = g_new0(struct QJackThreadData, 1); + data->function = function; + data->arg = arg; + int ret = pthread_create(thread, attr, qjack_thread_trampoline, data); if (ret != 0) { + g_free(data); return ret; } - /* set the name of the thread */ - pthread_setname_np(*thread, "jack-client"); - return ret; } #endif @@ -695,7 +713,7 @@ static void register_audio_jack(void) { qemu_mutex_init(&qjack_shutdown_lock); audio_driver_register(&jack_driver); -#if !defined(WIN32) && defined(CONFIG_PTHREAD_SETNAME_NP_W_TID) +#if !defined(WIN32) jack_set_thread_creator(qjack_thread_creator); #endif jack_set_error_function(qjack_error); -- 2.52.0
The default main thread name is undefined, so use a constructor to explicitly set it to 'main'. This constructor is marked to run early as the thread name is intended to be used in error reporting / logs which may be triggered very early in QEMU execution. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/qemu-thread-posix.c | 6 ++++++ util/qemu-thread-win32.c | 6 ++++++ 2 files changed, 12 insertions(+) diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index b1c127dbe3..afeac9ecad 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -22,6 +22,12 @@ #include <pthread_np.h> #endif +static void __attribute__((__constructor__(QEMU_CONSTRUCTOR_EARLY))) +qemu_thread_init(void) +{ + qemu_thread_set_name("main"); +} + static void error_exit(int err, const char *msg) { fprintf(stderr, "qemu: %s: %s\n", msg, strerror(err)); diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 4d2d663a9a..8ca6429ad3 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -22,6 +22,12 @@ typedef HRESULT (WINAPI *pSetThreadDescription) (HANDLE hThread, static pSetThreadDescription SetThreadDescriptionFunc; static HMODULE kernel32_module; +static void __attribute__((__constructor__(QEMU_CONSTRUCTOR_EARLY))) +qemu_thread_init(void) +{ + qemu_thread_set_name("main"); +} + static bool load_set_thread_description(void) { static gsize _init_once = 0; -- 2.52.0
On 1/8/26 18:03, Daniel P. Berrangé wrote:
The default main thread name is undefined, so use a constructor to explicitly set it to 'main'. This constructor is marked to run early as the thread name is intended to be used in error reporting / logs which may be triggered very early in QEMU execution.
At least on Linux I don't think we want to call the pthread function. Since pthread_setname_np writes to /proc/self/task/tid/comm, wouldn't that cause ps to show qemu processes as "main" instead of "qemu" or "qemu-kvm"? Paolo
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/qemu-thread-posix.c | 6 ++++++ util/qemu-thread-win32.c | 6 ++++++ 2 files changed, 12 insertions(+)
diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index b1c127dbe3..afeac9ecad 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -22,6 +22,12 @@ #include <pthread_np.h> #endif
+static void __attribute__((__constructor__(QEMU_CONSTRUCTOR_EARLY))) +qemu_thread_init(void) +{ + qemu_thread_set_name("main"); +} + static void error_exit(int err, const char *msg) { fprintf(stderr, "qemu: %s: %s\n", msg, strerror(err)); diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 4d2d663a9a..8ca6429ad3 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -22,6 +22,12 @@ typedef HRESULT (WINAPI *pSetThreadDescription) (HANDLE hThread, static pSetThreadDescription SetThreadDescriptionFunc; static HMODULE kernel32_module;
+static void __attribute__((__constructor__(QEMU_CONSTRUCTOR_EARLY))) +qemu_thread_init(void) +{ + qemu_thread_set_name("main"); +} + static bool load_set_thread_description(void) { static gsize _init_once = 0;
On Fri, Jan 09, 2026 at 12:45:03PM +0100, Paolo Bonzini wrote:
On 1/8/26 18:03, Daniel P. Berrangé wrote:
The default main thread name is undefined, so use a constructor to explicitly set it to 'main'. This constructor is marked to run early as the thread name is intended to be used in error reporting / logs which may be triggered very early in QEMU execution.
At least on Linux I don't think we want to call the pthread function.
Since pthread_setname_np writes to /proc/self/task/tid/comm, wouldn't that cause ps to show qemu processes as "main" instead of "qemu" or "qemu-kvm"?
Hmmm, it depends on the 'ps' options you use: $ ./build/qemu-system-x86_64 & [3] 3859009 ⚙️ [oci:fedora-43 qemu]$ ps | grep 3859009 3859009 pts/10 00:00:04 main ⚙️ [oci:fedora-43 qemu]$ ps -a | grep 3859009 3859009 pts/10 00:00:03 main ⚙️ [oci:fedora-43 qemu]$ ps -ax | grep 3859009 3859009 pts/10 Sl 0:03 ./build/qemu-system-x86_64 ⚙️ [oci:fedora-43 qemu]$ ps -au | grep 3859009 berrange 3859009 8.6 0.1 3893224 123700 pts/10 Sl 11:49 0:04 ./build/qemu-system-x86_64 ⚙️ [oci:fedora-43 qemu]$ ps -af | grep 3859009 berrange 3859009 2085609 8 11:49 pts/10 00:00:04 ./build/qemu-system-x86_64 ⚙️ [oci:fedora-43 qemu]$ ps -axuwf | grep 3859009 berrange 3859009 53.4 0.1 3905536 124108 pts/10 Sl 11:49 0:03 | \_ ./build/qemu-system-x86_64 and I hadn't noticed since I always use one of the latter sets of options that give the true name.
Paolo
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/qemu-thread-posix.c | 6 ++++++ util/qemu-thread-win32.c | 6 ++++++ 2 files changed, 12 insertions(+)
diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index b1c127dbe3..afeac9ecad 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -22,6 +22,12 @@ #include <pthread_np.h> #endif +static void __attribute__((__constructor__(QEMU_CONSTRUCTOR_EARLY))) +qemu_thread_init(void) +{ + qemu_thread_set_name("main"); +} + static void error_exit(int err, const char *msg) { fprintf(stderr, "qemu: %s: %s\n", msg, strerror(err)); diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 4d2d663a9a..8ca6429ad3 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -22,6 +22,12 @@ typedef HRESULT (WINAPI *pSetThreadDescription) (HANDLE hThread, static pSetThreadDescription SetThreadDescriptionFunc; static HMODULE kernel32_module; +static void __attribute__((__constructor__(QEMU_CONSTRUCTOR_EARLY))) +qemu_thread_init(void) +{ + qemu_thread_set_name("main"); +} + static bool load_set_thread_description(void) { static gsize _init_once = 0;
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 :|
On 1/9/26 12:52, Daniel P. Berrangé wrote:
On Fri, Jan 09, 2026 at 12:45:03PM +0100, Paolo Bonzini wrote:
On 1/8/26 18:03, Daniel P. Berrangé wrote:
The default main thread name is undefined, so use a constructor to explicitly set it to 'main'. This constructor is marked to run early as the thread name is intended to be used in error reporting / logs which may be triggered very early in QEMU execution.
At least on Linux I don't think we want to call the pthread function.
Since pthread_setname_np writes to /proc/self/task/tid/comm, wouldn't that cause ps to show qemu processes as "main" instead of "qemu" or "qemu-kvm"?
Hmmm, it depends on the 'ps' options you use:
$ ./build/qemu-system-x86_64 & [3] 3859009
⚙️ [oci:fedora-43 qemu]$ ps | grep 3859009 3859009 pts/10 00:00:04 main ⚙️ [oci:fedora-43 qemu]$ ps -a | grep 3859009 3859009 pts/10 00:00:03 main ⚙️ [oci:fedora-43 qemu]$ ps -ax | grep 3859009 3859009 pts/10 Sl 0:03 ./build/qemu-system-x86_64 ⚙️ [oci:fedora-43 qemu]$ ps -au | grep 3859009 berrange 3859009 8.6 0.1 3893224 123700 pts/10 Sl 11:49 0:04 ./build/qemu-system-x86_64 ⚙️ [oci:fedora-43 qemu]$ ps -af | grep 3859009 berrange 3859009 2085609 8 11:49 pts/10 00:00:04 ./build/qemu-system-x86_64 ⚙️ [oci:fedora-43 qemu]$ ps -axuwf | grep 3859009 berrange 3859009 53.4 0.1 3905536 124108 pts/10 Sl 11:49 0:03 | \_ ./build/qemu-system-x86_64
and I hadn't noticed since I always use one of the latter sets of options that give the true name.
FWIW "top" also changes its process name to "main"; there's precedent for Firefox *not* changing it: $ ps -o "%c" $(pidof firefox) COMMAND firefox forkserver Socket Process Privileged Cont ... Since we can't really know how the COMM is being used by monitoring tools, and there's a simple workaround within QEMU, I'd prefer avoiding this. Sorry for not spotting it earlier. Paolo
This will be used to include the thread name in error reports in a later patch. It returns a const string stored in a thread local to avoid memory allocation when it is called repeatedly in a single thread. The thread name should be set at the very start of the thread execution, which is the case when using qemu_thread_create. Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + meson.build | 21 +++++++++++++++++ util/qemu-thread-posix.c | 33 ++++++++++++++++++++++++++- util/qemu-thread-win32.c | 49 ++++++++++++++++++++++++++++++++++++---- 4 files changed, 99 insertions(+), 5 deletions(-) diff --git a/include/qemu/thread.h b/include/qemu/thread.h index 27b888ab0a..98cc5c41ac 100644 --- a/include/qemu/thread.h +++ b/include/qemu/thread.h @@ -216,6 +216,7 @@ void qemu_thread_get_self(QemuThread *thread); bool qemu_thread_is_self(QemuThread *thread); G_NORETURN void qemu_thread_exit(void *retval); void qemu_thread_set_name(const char *name); +const char *qemu_thread_get_name(void); struct Notifier; /** diff --git a/meson.build b/meson.build index db87358d62..eb27aca329 100644 --- a/meson.build +++ b/meson.build @@ -2874,6 +2874,27 @@ config_host_data.set('CONFIG_PTHREAD_SET_NAME_NP', cc.links(osdep_prefix + ''' pthread_set_name_np(thread, "QEMU"); return 0; }''', dependencies: threads)) + +config_host_data.set('CONFIG_PTHREAD_GETNAME_NP', cc.links(osdep_prefix + ''' + #include <pthread.h> + + int main(void) + { + char buf[16]; + pthread_getname_np(pthread_self(), buf, sizeof(buf)); + return 0; + }''', dependencies: threads)) +config_host_data.set('CONFIG_PTHREAD_GET_NAME_NP', cc.links(osdep_prefix + ''' + #include <pthread.h> + #include <pthread_np.h> + + int main(void) + { + char buf[16]; + pthread_get_name_np(pthread_self(), buf, sizeof(buf)); + return 0; + }''', dependencies: threads)) + config_host_data.set('CONFIG_PTHREAD_CONDATTR_SETCLOCK', cc.links(osdep_prefix + ''' #include <pthread.h> diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index afeac9ecad..47156b60ce 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -18,7 +18,7 @@ #include "qemu/tsan.h" #include "qemu/bitmap.h" -#ifdef CONFIG_PTHREAD_SET_NAME_NP +#if defined(CONFIG_PTHREAD_SET_NAME_NP) || defined(CONFIG_PTHREAD_GET_NAME_NP) #include <pthread_np.h> #endif @@ -532,3 +532,34 @@ void *qemu_thread_join(QemuThread *thread) } return ret; } + +/* + * This is not defined on Linux, but the man page indicates + * the buffer must be at least 16 bytes, including the NUL + * terminator + */ +#ifndef PTHREAD_MAX_NAMELEN_NP +#define PTHREAD_MAX_NAMELEN_NP 16 +#endif + +static __thread char namebuf[PTHREAD_MAX_NAMELEN_NP]; + +const char *qemu_thread_get_name(void) +{ + int rv; + if (namebuf[0] != '\0') { + return namebuf; + } + +# if defined(CONFIG_PTHREAD_GETNAME_NP) + rv = pthread_getname_np(pthread_self(), namebuf, sizeof(namebuf)); +# elif defined(CONFIG_PTHREAD_GET_NAME_NP) + rv = pthread_get_name_np(pthread_self(), namebuf, sizeof(namebuf)); +# else + rv = -1; +# endif + if (rv != 0) { + g_strlcpy(namebuf, "unnamed", G_N_ELEMENTS(namebuf)); + } + return namebuf; +} diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 8ca6429ad3..082a38c7d5 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -19,7 +19,10 @@ typedef HRESULT (WINAPI *pSetThreadDescription) (HANDLE hThread, PCWSTR lpThreadDescription); +typedef HRESULT (WINAPI *pGetThreadDescription) (HANDLE hThread, + PWSTR *lpThreadDescription); static pSetThreadDescription SetThreadDescriptionFunc; +static pGetThreadDescription GetThreadDescriptionFunc; static HMODULE kernel32_module; static void __attribute__((__constructor__(QEMU_CONSTRUCTOR_EARLY))) @@ -28,7 +31,7 @@ qemu_thread_init(void) qemu_thread_set_name("main"); } -static bool load_set_thread_description(void) +static bool load_thread_description(void) { static gsize _init_once = 0; @@ -38,14 +41,17 @@ static bool load_set_thread_description(void) SetThreadDescriptionFunc = (pSetThreadDescription)GetProcAddress(kernel32_module, "SetThreadDescription"); - if (!SetThreadDescriptionFunc) { + GetThreadDescriptionFunc = + (pGetThreadDescription)GetProcAddress(kernel32_module, + "GetThreadDescription"); + if (!SetThreadDescriptionFunc || !GetThreadDescriptionFunc) { FreeLibrary(kernel32_module); } } g_once_init_leave(&_init_once, 1); } - return !!SetThreadDescriptionFunc; + return (SetThreadDescriptionFunc && GetThreadDescriptionFunc); } static void error_exit(int err, const char *msg) @@ -331,7 +337,7 @@ void qemu_thread_set_name(const char *name) { g_autofree wchar_t *namew = NULL; - if (!load_set_thread_description()) { + if (!load_thread_description()) { return; } @@ -415,3 +421,38 @@ bool qemu_thread_is_self(QemuThread *thread) { return GetCurrentThreadId() == thread->tid; } + +static __thread char namebuf[64]; + +const char *qemu_thread_get_name(void) +{ + HRESULT hr; + wchar_t *namew = NULL; + g_autofree char *name = NULL; + + if (namebuf[0] != '\0') { + return namebuf; + } + + if (!load_thread_description()) { + goto error; + } + + hr = GetThreadDescriptionFunc(GetCurrentThread(), &namew); + if (!SUCCEEDED(hr)) { + goto error; + } + + name = g_utf16_to_utf8(namew, -1, NULL, NULL, NULL); + LocalFree(namew); + if (!name) { + goto error; + } + + g_strlcpy(namebuf, name, G_N_ELEMENTS(namebuf)); + return namebuf; + + error: + g_strlcpy(namebuf, "unnamed", G_N_ELEMENTS(namebuf)); + return namebuf; +} -- 2.52.0
On 1/8/26 18:03, Daniel P. Berrangé wrote:
+static __thread char namebuf[PTHREAD_MAX_NAMELEN_NP];
... you can instead of the previous patch, add a constructor here that just sets namebuf to "main" with strcpy. For Windows on the other hand it should be okay to call SetThreadDescription if available. Paolo
On Fri, Jan 09, 2026 at 12:49:20PM +0100, Paolo Bonzini wrote:
On 1/8/26 18:03, Daniel P. Berrangé wrote:
+static __thread char namebuf[PTHREAD_MAX_NAMELEN_NP];
... you can instead of the previous patch, add a constructor here that just sets namebuf to "main" with strcpy.
How about just a static initializer static __thread char namebuf[PTHREAD_MAX_NAMELEN_NP] = { 'm', 'a', 'i', 'n', '\0' }; or is there some interaction with __thread that makes that undesirable ? The downside is that I wanted the nice thread names to appear in GDB too, but I guess we can live with the main thread being unnamed in GDB.
For Windows on the other hand it should be okay to call SetThreadDescription if available.
Paolo
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 :|
On 1/9/26 12:56, Daniel P. Berrangé wrote:
On Fri, Jan 09, 2026 at 12:49:20PM +0100, Paolo Bonzini wrote:
On 1/8/26 18:03, Daniel P. Berrangé wrote:
+static __thread char namebuf[PTHREAD_MAX_NAMELEN_NP];
... you can instead of the previous patch, add a constructor here that just sets namebuf to "main" with strcpy.
How about just a static initializer
static __thread char namebuf[PTHREAD_MAX_NAMELEN_NP] = { 'm', 'a', 'i', 'n', '\0' };
or is there some interaction with __thread that makes that undesirable ?
This would break here: if (namebuf[0] != '\0') { return namebuf; } and every thread would have "main" as the name, because static initializers for __thread apply to all threads. Thanks, Paolo
Daniel P. Berrangé <berrange@redhat.com> writes:
This will be used to include the thread name in error reports in a later patch. It returns a const string stored in a thread local to avoid memory allocation when it is called repeatedly in a single thread. The thread name should be set at the very start of the thread execution, which is the case when using qemu_thread_create.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + meson.build | 21 +++++++++++++++++ util/qemu-thread-posix.c | 33 ++++++++++++++++++++++++++- util/qemu-thread-win32.c | 49 ++++++++++++++++++++++++++++++++++++---- 4 files changed, 99 insertions(+), 5 deletions(-)
Tempted to store the thread name in TLS and call it a day.
On Tue, Jan 13, 2026 at 10:27:04AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
This will be used to include the thread name in error reports in a later patch. It returns a const string stored in a thread local to avoid memory allocation when it is called repeatedly in a single thread. The thread name should be set at the very start of the thread execution, which is the case when using qemu_thread_create.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + meson.build | 21 +++++++++++++++++ util/qemu-thread-posix.c | 33 ++++++++++++++++++++++++++- util/qemu-thread-win32.c | 49 ++++++++++++++++++++++++++++++++++++---- 4 files changed, 99 insertions(+), 5 deletions(-)
Tempted to store the thread name in TLS and call it a day.
Using the official APIs in this way ensures that the thread name is visible outside QEMU. For example when debugging in GDB, which IMHO is an important benefit. 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 :|
Daniel P. Berrangé <berrange@redhat.com> writes:
On Tue, Jan 13, 2026 at 10:27:04AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
This will be used to include the thread name in error reports in a later patch. It returns a const string stored in a thread local to avoid memory allocation when it is called repeatedly in a single thread. The thread name should be set at the very start of the thread execution, which is the case when using qemu_thread_create.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + meson.build | 21 +++++++++++++++++ util/qemu-thread-posix.c | 33 ++++++++++++++++++++++++++- util/qemu-thread-win32.c | 49 ++++++++++++++++++++++++++++++++++++---- 4 files changed, 99 insertions(+), 5 deletions(-)
Tempted to store the thread name in TLS and call it a day.
Using the official APIs in this way ensures that the thread name is visible outside QEMU. For example when debugging in GDB, which IMHO is an important benefit.
I didn't mean to suggest not to set the "official" thread name. This patch retrieves the "official" thread name back. Takes a bit of system-specific code, including Meson magic. We could instead hold on to our own copy, and just use that.
On Tue, Jan 13, 2026 at 2:00 PM Markus Armbruster <armbru@redhat.com> wrote:
Tempted to store the thread name in TLS and call it a day.
Using the official APIs in this way ensures that the thread name is visible outside QEMU. For example when debugging in GDB, which IMHO is an important benefit.
I didn't mean to suggest not to set the "official" thread name.
This patch retrieves the "official" thread name back. Takes a bit of system-specific code, including Meson magic. We could instead hold on to our own copy, and just use that.
Yes, I think that's what we're going to do anyway due to my remark on patch 7/24. Paolo
On Tue, Jan 13, 2026 at 04:49:53PM +0100, Paolo Bonzini wrote:
On Tue, Jan 13, 2026 at 2:00 PM Markus Armbruster <armbru@redhat.com> wrote:
Tempted to store the thread name in TLS and call it a day.
Using the official APIs in this way ensures that the thread name is visible outside QEMU. For example when debugging in GDB, which IMHO is an important benefit.
I didn't mean to suggest not to set the "official" thread name.
This patch retrieves the "official" thread name back. Takes a bit of system-specific code, including Meson magic. We could instead hold on to our own copy, and just use that.
Yes, I think that's what we're going to do anyway due to my remark on patch 7/24.
That doesn't alter things. The constructor merely initialzies the name for the main thread. We'll still use pthread APIs for all other threads. 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 :|
On Tue, Jan 13, 2026 at 02:00:35PM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
On Tue, Jan 13, 2026 at 10:27:04AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
This will be used to include the thread name in error reports in a later patch. It returns a const string stored in a thread local to avoid memory allocation when it is called repeatedly in a single thread. The thread name should be set at the very start of the thread execution, which is the case when using qemu_thread_create.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/thread.h | 1 + meson.build | 21 +++++++++++++++++ util/qemu-thread-posix.c | 33 ++++++++++++++++++++++++++- util/qemu-thread-win32.c | 49 ++++++++++++++++++++++++++++++++++++---- 4 files changed, 99 insertions(+), 5 deletions(-)
Tempted to store the thread name in TLS and call it a day.
Using the official APIs in this way ensures that the thread name is visible outside QEMU. For example when debugging in GDB, which IMHO is an important benefit.
I didn't mean to suggest not to set the "official" thread name.
This patch retrieves the "official" thread name back. Takes a bit of system-specific code, including Meson magic. We could instead hold on to our own copy, and just use that.
That would mean we don't get any names for threads which are spawned indirectly. There are quite a lot of libraries that QEMU can use, which can spawn threads behind QEMU's back, and these threads can still be running QEMU code through callbacks. spice, gstreamer, jack and librbd are some I know that spawn threads, but there are likely quite a few more. In the the jack case we hook into its thread creation to set a name ourselves, but we can't rely on that in general, and these libraries may well have set thread names we should use. I want to maximise the cases where we can retrieve a thread name. While the code is more verbose than I'd like, it exists now so I don't think its good to throw it away to put into a worse solution. 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 :|
There is a gotcha with qemu_log() usage in a threaded process. If fragments of a log message are output via qemu_log() it is possible for messages from two threads to get mixed up. To prevent this qemu_log_trylock() should be used, along with fprintf(f) calls. This is a subtle problem that needs to be explained in the API docs to ensure correct usage. Reported-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/log-for-trace.h | 17 ++++++++++++++++- include/qemu/log.h | 31 +++++++++++++++++++++++++++++++ rust/util/src/log.rs | 6 ++++++ 3 files changed, 53 insertions(+), 1 deletion(-) diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h index f3a8791f1d..6861a1a4b7 100644 --- a/include/qemu/log-for-trace.h +++ b/include/qemu/log-for-trace.h @@ -29,7 +29,22 @@ static inline bool qemu_loglevel_mask(int mask) return (qemu_loglevel & mask) != 0; } -/* main logging function */ +/** + * qemu_log: report a log message + * @fmt: the format string for the message + * @...: the format string arguments + * + * This will emit a log message to the current output stream. + * + * The @fmt string should normally represent a complete line + * of text, and thus end with a newline character. + * + * While it is possible to incrementally output fragments of + * a complete line using qemu_log, this is inefficient and + * races with other threads. For outputting fragments it is + * strongly preferred to use the qemu_log_trylock() method + * combined with fprintf(). + */ void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...); #endif diff --git a/include/qemu/log.h b/include/qemu/log.h index 7effba4da4..e9d3c6806b 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -41,7 +41,38 @@ bool qemu_log_separate(void); /* Lock/unlock output. */ +/** + * Acquires a lock on the current log output stream. + * The returned FILE object should be used with the + * fprintf() function to output the log message, and + * then qemu_log_unlock() called to release the lock. + * + * The primary use case is to be able to incrementally + * output fragments of a complete log message in an + * efficient and race free manner. + * + * The simpler qemu_log() method must only be used + * to output complete log messages. + * + * A typical usage pattern would be + * + * FILE *f = qemu_log_trylock() + * + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "The end\n"); + * + * qemu_log_unlock(f); + * + * Returns: the current FILE if available, NULL on error + */ FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT; + +/** + * Releases the lock on the log output, previously + * acquired by qemu_log_trylock(). + */ void qemu_log_unlock(FILE *fd); /* Logging functions: */ diff --git a/rust/util/src/log.rs b/rust/util/src/log.rs index 0a4bc4249a..6a3a30d8d8 100644 --- a/rust/util/src/log.rs +++ b/rust/util/src/log.rs @@ -134,6 +134,12 @@ fn drop(&mut self) { /// "Address 0x{:x} out of range", /// error_address, /// ); +/// +/// The `log_mask_ln` macro should only be used for emitting complete +/// log messages. Where it is required to incrementally output string +/// fragments to construct a complete message, `LogGuard::new()` should +/// be directly used in combination with `writeln()` to avoid output +/// races with other QEMU threads. /// ``` #[macro_export] macro_rules! log_mask_ln { -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
There is a gotcha with qemu_log() usage in a threaded process. If fragments of a log message are output via qemu_log() it is possible for messages from two threads to get mixed up. To prevent this qemu_log_trylock() should be used, along with fprintf(f) calls.
This is a subtle problem that needs to be explained in the API docs to ensure correct usage.
Reported-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/log-for-trace.h | 17 ++++++++++++++++- include/qemu/log.h | 31 +++++++++++++++++++++++++++++++ rust/util/src/log.rs | 6 ++++++ 3 files changed, 53 insertions(+), 1 deletion(-)
diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h index f3a8791f1d..6861a1a4b7 100644 --- a/include/qemu/log-for-trace.h +++ b/include/qemu/log-for-trace.h @@ -29,7 +29,22 @@ static inline bool qemu_loglevel_mask(int mask) return (qemu_loglevel & mask) != 0; }
-/* main logging function */ +/** + * qemu_log: report a log message + * @fmt: the format string for the message + * @...: the format string arguments + * + * This will emit a log message to the current output stream. + * + * The @fmt string should normally represent a complete line + * of text, and thus end with a newline character.
Note for later: "should normally".
+ * + * While it is possible to incrementally output fragments of + * a complete line using qemu_log, this is inefficient and + * races with other threads. For outputting fragments it is + * strongly preferred to use the qemu_log_trylock() method + * combined with fprintf(). + */ void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
#endif diff --git a/include/qemu/log.h b/include/qemu/log.h index 7effba4da4..e9d3c6806b 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -41,7 +41,38 @@ bool qemu_log_separate(void);
/* Lock/unlock output. */
+/** + * Acquires a lock on the current log output stream. + * The returned FILE object should be used with the + * fprintf() function to output the log message, and + * then qemu_log_unlock() called to release the lock. + * + * The primary use case is to be able to incrementally + * output fragments of a complete log message in an + * efficient and race free manner. + * + * The simpler qemu_log() method must only be used + * to output complete log messages.
"must".
+ * + * A typical usage pattern would be + * + * FILE *f = qemu_log_trylock() + * + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "The end\n"); + * + * qemu_log_unlock(f); + * + * Returns: the current FILE if available, NULL on error + */ FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT; + +/** + * Releases the lock on the log output, previously + * acquired by qemu_log_trylock(). + */ void qemu_log_unlock(FILE *fd);
/* Logging functions: */ diff --git a/rust/util/src/log.rs b/rust/util/src/log.rs index 0a4bc4249a..6a3a30d8d8 100644 --- a/rust/util/src/log.rs +++ b/rust/util/src/log.rs @@ -134,6 +134,12 @@ fn drop(&mut self) { /// "Address 0x{:x} out of range", /// error_address, /// ); +/// +/// The `log_mask_ln` macro should only be used for emitting complete
"should only".
+/// log messages. Where it is required to incrementally output string +/// fragments to construct a complete message, `LogGuard::new()` should +/// be directly used in combination with `writeln()` to avoid output +/// races with other QEMU threads. /// ``` #[macro_export] macro_rules! log_mask_ln {
"Should normally" suggests there are exceptions. "Should only" does not. "Must" is a bit stronger still. Which of the three do we want?
On Tue, Jan 13, 2026 at 10:59:49AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
There is a gotcha with qemu_log() usage in a threaded process. If fragments of a log message are output via qemu_log() it is possible for messages from two threads to get mixed up. To prevent this qemu_log_trylock() should be used, along with fprintf(f) calls.
This is a subtle problem that needs to be explained in the API docs to ensure correct usage.
Reported-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/log-for-trace.h | 17 ++++++++++++++++- include/qemu/log.h | 31 +++++++++++++++++++++++++++++++ rust/util/src/log.rs | 6 ++++++ 3 files changed, 53 insertions(+), 1 deletion(-)
diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h index f3a8791f1d..6861a1a4b7 100644 --- a/include/qemu/log-for-trace.h +++ b/include/qemu/log-for-trace.h @@ -29,7 +29,22 @@ static inline bool qemu_loglevel_mask(int mask) return (qemu_loglevel & mask) != 0; }
-/* main logging function */ +/** + * qemu_log: report a log message + * @fmt: the format string for the message + * @...: the format string arguments + * + * This will emit a log message to the current output stream. + * + * The @fmt string should normally represent a complete line + * of text, and thus end with a newline character.
Note for later: "should normally".
+ * + * While it is possible to incrementally output fragments of + * a complete line using qemu_log, this is inefficient and + * races with other threads. For outputting fragments it is + * strongly preferred to use the qemu_log_trylock() method + * combined with fprintf(). + */ void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
#endif diff --git a/include/qemu/log.h b/include/qemu/log.h index 7effba4da4..e9d3c6806b 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -41,7 +41,38 @@ bool qemu_log_separate(void);
/* Lock/unlock output. */
+/** + * Acquires a lock on the current log output stream. + * The returned FILE object should be used with the + * fprintf() function to output the log message, and + * then qemu_log_unlock() called to release the lock. + * + * The primary use case is to be able to incrementally + * output fragments of a complete log message in an + * efficient and race free manner. + * + * The simpler qemu_log() method must only be used + * to output complete log messages.
"must".
+ * + * A typical usage pattern would be + * + * FILE *f = qemu_log_trylock() + * + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "The end\n"); + * + * qemu_log_unlock(f); + * + * Returns: the current FILE if available, NULL on error + */ FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT; + +/** + * Releases the lock on the log output, previously + * acquired by qemu_log_trylock(). + */ void qemu_log_unlock(FILE *fd);
/* Logging functions: */ diff --git a/rust/util/src/log.rs b/rust/util/src/log.rs index 0a4bc4249a..6a3a30d8d8 100644 --- a/rust/util/src/log.rs +++ b/rust/util/src/log.rs @@ -134,6 +134,12 @@ fn drop(&mut self) { /// "Address 0x{:x} out of range", /// error_address, /// ); +/// +/// The `log_mask_ln` macro should only be used for emitting complete
"should only".
+/// log messages. Where it is required to incrementally output string +/// fragments to construct a complete message, `LogGuard::new()` should +/// be directly used in combination with `writeln()` to avoid output +/// races with other QEMU threads. /// ``` #[macro_export] macro_rules! log_mask_ln {
"Should normally" suggests there are exceptions.
"Should only" does not.
"Must" is a bit stronger still.
Which of the three do we want?
The "Should" usage was reflecting the reality that we have quite alot of code using qemu_log_trylock + qemu_log, instead of qemu_log_trylock + fprintf. I didn't feel it appropriate to use 'must' unless we explicitly make qemu_log() fail when used inside the scope of a qemu_log_trylock(). So "Should normally" is the best fit 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 :|
On Tue, Jan 13, 2026 at 10:49:01AM +0000, Daniel P. Berrangé via Devel wrote:
On Tue, Jan 13, 2026 at 10:59:49AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
There is a gotcha with qemu_log() usage in a threaded process. If fragments of a log message are output via qemu_log() it is possible for messages from two threads to get mixed up. To prevent this qemu_log_trylock() should be used, along with fprintf(f) calls.
This is a subtle problem that needs to be explained in the API docs to ensure correct usage.
Reported-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/log-for-trace.h | 17 ++++++++++++++++- include/qemu/log.h | 31 +++++++++++++++++++++++++++++++ rust/util/src/log.rs | 6 ++++++ 3 files changed, 53 insertions(+), 1 deletion(-)
diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h index f3a8791f1d..6861a1a4b7 100644 --- a/include/qemu/log-for-trace.h +++ b/include/qemu/log-for-trace.h @@ -29,7 +29,22 @@ static inline bool qemu_loglevel_mask(int mask) return (qemu_loglevel & mask) != 0; }
-/* main logging function */ +/** + * qemu_log: report a log message + * @fmt: the format string for the message + * @...: the format string arguments + * + * This will emit a log message to the current output stream. + * + * The @fmt string should normally represent a complete line + * of text, and thus end with a newline character.
Note for later: "should normally".
+ * + * While it is possible to incrementally output fragments of + * a complete line using qemu_log, this is inefficient and + * races with other threads. For outputting fragments it is + * strongly preferred to use the qemu_log_trylock() method + * combined with fprintf(). + */ void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
#endif diff --git a/include/qemu/log.h b/include/qemu/log.h index 7effba4da4..e9d3c6806b 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -41,7 +41,38 @@ bool qemu_log_separate(void);
/* Lock/unlock output. */
+/** + * Acquires a lock on the current log output stream. + * The returned FILE object should be used with the + * fprintf() function to output the log message, and + * then qemu_log_unlock() called to release the lock. + * + * The primary use case is to be able to incrementally + * output fragments of a complete log message in an + * efficient and race free manner. + * + * The simpler qemu_log() method must only be used + * to output complete log messages.
"must".
+ * + * A typical usage pattern would be + * + * FILE *f = qemu_log_trylock() + * + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "The end\n"); + * + * qemu_log_unlock(f); + * + * Returns: the current FILE if available, NULL on error + */ FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT; + +/** + * Releases the lock on the log output, previously + * acquired by qemu_log_trylock(). + */ void qemu_log_unlock(FILE *fd);
/* Logging functions: */ diff --git a/rust/util/src/log.rs b/rust/util/src/log.rs index 0a4bc4249a..6a3a30d8d8 100644 --- a/rust/util/src/log.rs +++ b/rust/util/src/log.rs @@ -134,6 +134,12 @@ fn drop(&mut self) { /// "Address 0x{:x} out of range", /// error_address, /// ); +/// +/// The `log_mask_ln` macro should only be used for emitting complete
"should only".
+/// log messages. Where it is required to incrementally output string +/// fragments to construct a complete message, `LogGuard::new()` should +/// be directly used in combination with `writeln()` to avoid output +/// races with other QEMU threads. /// ``` #[macro_export] macro_rules! log_mask_ln {
"Should normally" suggests there are exceptions.
"Should only" does not.
"Must" is a bit stronger still.
Which of the three do we want?
The "Should" usage was reflecting the reality that we have quite alot of code using qemu_log_trylock + qemu_log, instead of qemu_log_trylock + fprintf.
I didn't feel it appropriate to use 'must' unless we explicitly make qemu_log() fail when used inside the scope of a qemu_log_trylock().
So "Should normally" is the best fit
Actually specifically in the log.rs case, we have a greater constraint. The rust code for log_mask_ln will unconditionally add a newline to all messages. So this Rust method *must* only be usd for complete messages, regardless of what policy we have on the C qemu_log() call. 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 :|
Daniel P. Berrangé <berrange@redhat.com> writes:
On Tue, Jan 13, 2026 at 10:49:01AM +0000, Daniel P. Berrangé via Devel wrote:
On Tue, Jan 13, 2026 at 10:59:49AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
There is a gotcha with qemu_log() usage in a threaded process. If fragments of a log message are output via qemu_log() it is possible for messages from two threads to get mixed up. To prevent this qemu_log_trylock() should be used, along with fprintf(f) calls.
This is a subtle problem that needs to be explained in the API docs to ensure correct usage.
Reported-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
[...]
"Should normally" suggests there are exceptions.
"Should only" does not.
"Must" is a bit stronger still.
Which of the three do we want?
The "Should" usage was reflecting the reality that we have quite alot of code using qemu_log_trylock + qemu_log, instead of qemu_log_trylock + fprintf.
Yes.
I didn't feel it appropriate to use 'must' unless we explicitly make qemu_log() fail when used inside the scope of a qemu_log_trylock().
Fair.
So "Should normally" is the best fit
Actually specifically in the log.rs case, we have a greater constraint. The rust code for log_mask_ln will unconditionally add a newline to all messages. So this Rust method *must* only be usd for complete messages, regardless of what policy we have on the C qemu_log() call.
Got it. Suggest to consistently use "should normally" in the contracts where it is the best fit. Use "must" for the Rust method, and maybe mention it in the commit message (you decide).
There are three general patterns to QEMU log output 1. Single complete message calls qemu_log("Some message\n"); 2. Direct use of fprintf FILE *f = qemu_log_trylock() fprintf(f, "..."); fprintf(f, "..."); fprintf(f, "...\n"); qemu_log_unlock(f) 3. Mixed use of qemu_log_trylock/qemu_log() FILE *f = qemu_log_trylock() qemu_log("...."); qemu_log("...."); qemu_log("....\n"); qemu_log_unlock(f) When message prefixes are enabled, the timestamp will be unconditionally emitted for all qemu_log() calls. This works fine in the 1st case, and has no effect in the 2nd case. In the 3rd case, however, we get the timestamp printed over & over in each fragment. One can suggest that pattern (3) is pointless as it is functionally identical to (2) but with extra indirection and overhead. None the less we have a fair bit of code that does this. The qemu_log() call itself is nothing more than a wrapper which does pattern (2) with a single fprintf() call. One might question whether (2) should include the message prefix in the same way that (1), but there are scenarios where this could be inappropriate / unhelpful such as the CPU register dumps or linux-user strace output. This patch fixes the problem in pattern (3) by keeping track of the call depth of qemu_log_trylock() and then only emitting the the prefix when the starting depth was zero. In doing this qemu_log_trylock_context() is also introduced as a variant of qemu_log_trylock() that emits the prefix. Callers doing to batch output can thus choose whether a prefix is appropriate or not. Fixes: 012842c07552 (log: make '-msg timestamp=on' apply to all qemu_log usage) Reported-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/log.h | 7 +++++++ util/log.c | 49 ++++++++++++++++++++++++++-------------------- 2 files changed, 35 insertions(+), 21 deletions(-) diff --git a/include/qemu/log.h b/include/qemu/log.h index e9d3c6806b..95f417c2b7 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -69,6 +69,13 @@ bool qemu_log_separate(void); */ FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT; +/** + * As qemu_log_trylock(), but will also print the message + * context, if any is configured and this caused the + * acquisition of the FILE lock + */ +FILE *qemu_log_trylock_context(void) G_GNUC_WARN_UNUSED_RESULT; + /** * Releases the lock on the log output, previously * acquired by qemu_log_trylock(). diff --git a/util/log.c b/util/log.c index c44d66b5ce..2ce7286f31 100644 --- a/util/log.c +++ b/util/log.c @@ -127,13 +127,39 @@ static FILE *qemu_log_trylock_with_err(Error **errp) return logfile; } +/* + * Zero if there's been no opening qemu_log_trylock call, + * indicating the need for message context to be emitted + * + * Non-zero if we're in the middle of printing a message, + * possibly over multiple lines and must skip further + * message context + */ +static __thread uint log_depth; + FILE *qemu_log_trylock(void) { - return qemu_log_trylock_with_err(NULL); + FILE *f = qemu_log_trylock_with_err(NULL); + log_depth++; + return f; +} + +FILE *qemu_log_trylock_context(void) +{ + FILE *f = qemu_log_trylock(); + if (log_depth == 1 && message_with_timestamp) { + g_autofree const char *timestr = NULL; + g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); + timestr = g_date_time_format_iso8601(dt); + fprintf(f, "%s ", timestr); + } + return f; } void qemu_log_unlock(FILE *logfile) { + assert(log_depth); + log_depth--; if (logfile) { fflush(logfile); qemu_funlockfile(logfile); @@ -145,28 +171,9 @@ void qemu_log_unlock(FILE *logfile) void qemu_log(const char *fmt, ...) { - FILE *f; - g_autofree const char *timestr = NULL; - - /* - * Prepare the timestamp *outside* the logging - * lock so it better reflects when the message - * was emitted if we are delayed acquiring the - * mutex - */ - if (message_with_timestamp) { - g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); - timestr = g_date_time_format_iso8601(dt); - } - - f = qemu_log_trylock(); + FILE *f = qemu_log_trylock_context(); if (f) { va_list ap; - - if (timestr) { - fprintf(f, "%s ", timestr); - } - va_start(ap, fmt); vfprintf(f, fmt, ap); va_end(ap); -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
There are three general patterns to QEMU log output
1. Single complete message calls
qemu_log("Some message\n");
2. Direct use of fprintf
FILE *f = qemu_log_trylock() fprintf(f, "..."); fprintf(f, "..."); fprintf(f, "...\n"); qemu_log_unlock(f)
3. Mixed use of qemu_log_trylock/qemu_log()
FILE *f = qemu_log_trylock() qemu_log("...."); qemu_log("...."); qemu_log("....\n"); qemu_log_unlock(f)
When message prefixes are enabled, the timestamp will be unconditionally emitted for all qemu_log() calls. This works fine in the 1st case, and has no effect in the 2nd case. In the 3rd case, however, we get the timestamp printed over & over in each fragment.
One can suggest that pattern (3) is pointless as it is functionally identical to (2) but with extra indirection and overhead. None the less we have a fair bit of code that does this.
The qemu_log() call itself is nothing more than a wrapper which does pattern (2) with a single fprintf() call.
One might question whether (2) should include the message prefix in the same way that (1), but there are scenarios where this could be inappropriate / unhelpful such as the CPU register dumps or linux-user strace output.
This patch fixes the problem in pattern (3) by keeping track of the call depth of qemu_log_trylock() and then only emitting the the prefix when the starting depth was zero. In doing this qemu_log_trylock_context() is also introduced as a variant of qemu_log_trylock() that emits the prefix. Callers doing to batch output can thus choose whether a prefix is appropriate or not.
I dislike pattern (3), but not nearly enough to chase it out of the tree myself. Hard to disagree with this patch then :)
Fixes: 012842c07552 (log: make '-msg timestamp=on' apply to all qemu_log usage) Reported-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/log.h | 7 +++++++ util/log.c | 49 ++++++++++++++++++++++++++-------------------- 2 files changed, 35 insertions(+), 21 deletions(-)
diff --git a/include/qemu/log.h b/include/qemu/log.h index e9d3c6806b..95f417c2b7 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -69,6 +69,13 @@ bool qemu_log_separate(void); */ FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT;
+/** + * As qemu_log_trylock(), but will also print the message + * context, if any is configured and this caused the + * acquisition of the FILE lock + */ +FILE *qemu_log_trylock_context(void) G_GNUC_WARN_UNUSED_RESULT;
This is used just once, in qemu_log(). Could be inlined into qemu_log(). If you prefer to keep it as a function, you could make it static. I wouldn't guess that this prints from the function name. Dunno, qemu_log_start_line()? Might want to pair it with a qemu_log_end_line() then. Telling function name is less important if it's static.
+ /** * Releases the lock on the log output, previously * acquired by qemu_log_trylock(). diff --git a/util/log.c b/util/log.c index c44d66b5ce..2ce7286f31 100644 --- a/util/log.c +++ b/util/log.c @@ -127,13 +127,39 @@ static FILE *qemu_log_trylock_with_err(Error **errp)
Not this patch's fault, but here goes anyway: static FILE *qemu_log_trylock_with_err(Error **errp) { FILE *logfile; logfile = thread_file; if (!logfile) { if (log_per_thread) { g_autofree char *filename = g_strdup_printf(global_filename, log_thread_id()); logfile = fopen(filename, "w"); if (!logfile) { error_setg_errno(errp, errno, "Error opening logfile %s for thread %d", filename, log_thread_id()); return NULL; } thread_file = logfile; qemu_log_thread_cleanup_notifier.notify = qemu_log_thread_cleanup; qemu_thread_atexit_add(&qemu_log_thread_cleanup_notifier); } else { rcu_read_lock(); /* * FIXME: typeof_strip_qual, as used by qatomic_rcu_read, * does not work with pointers to undefined structures, * such as we have with struct _IO_FILE and musl libc. * Since all we want is a read of a pointer, cast to void**, * which does work with typeof_strip_qual. */ logfile = qatomic_rcu_read((void **)&global_file); if (!logfile) { rcu_read_unlock(); return NULL; Fails without setting @errp. } } } qemu_flockfile(logfile);
return logfile; }
+/* + * Zero if there's been no opening qemu_log_trylock call, + * indicating the need for message context to be emitted + * + * Non-zero if we're in the middle of printing a message, + * possibly over multiple lines and must skip further + * message context + */ +static __thread uint log_depth; + FILE *qemu_log_trylock(void) { - return qemu_log_trylock_with_err(NULL); + FILE *f = qemu_log_trylock_with_err(NULL); + log_depth++; + return f; +} + +FILE *qemu_log_trylock_context(void) +{ + FILE *f = qemu_log_trylock();
This can fail, and if it does...
+ if (log_depth == 1 && message_with_timestamp) { + g_autofree const char *timestr = NULL; + g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); + timestr = g_date_time_format_iso8601(dt); + fprintf(f, "%s ", timestr);
... we crash here.
+ } + return f; }
void qemu_log_unlock(FILE *logfile) { + assert(log_depth); + log_depth--; if (logfile) { fflush(logfile); qemu_funlockfile(logfile); @@ -145,28 +171,9 @@ void qemu_log_unlock(FILE *logfile)
void qemu_log(const char *fmt, ...) { - FILE *f; - g_autofree const char *timestr = NULL; - - /* - * Prepare the timestamp *outside* the logging - * lock so it better reflects when the message - * was emitted if we are delayed acquiring the - * mutex - */ - if (message_with_timestamp) { - g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); - timestr = g_date_time_format_iso8601(dt); - } - - f = qemu_log_trylock(); + FILE *f = qemu_log_trylock_context(); if (f) { va_list ap; - - if (timestr) { - fprintf(f, "%s ", timestr); - } - va_start(ap, fmt); vfprintf(f, fmt, ap); va_end(ap);
On Tue, Jan 13, 2026 at 11:19:13AM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
There are three general patterns to QEMU log output
1. Single complete message calls
qemu_log("Some message\n");
2. Direct use of fprintf
FILE *f = qemu_log_trylock() fprintf(f, "..."); fprintf(f, "..."); fprintf(f, "...\n"); qemu_log_unlock(f)
3. Mixed use of qemu_log_trylock/qemu_log()
FILE *f = qemu_log_trylock() qemu_log("...."); qemu_log("...."); qemu_log("....\n"); qemu_log_unlock(f)
Fixes: 012842c07552 (log: make '-msg timestamp=on' apply to all qemu_log usage) Reported-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/log.h | 7 +++++++ util/log.c | 49 ++++++++++++++++++++++++++-------------------- 2 files changed, 35 insertions(+), 21 deletions(-)
diff --git a/include/qemu/log.h b/include/qemu/log.h index e9d3c6806b..95f417c2b7 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -69,6 +69,13 @@ bool qemu_log_separate(void); */ FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT;
+/** + * As qemu_log_trylock(), but will also print the message + * context, if any is configured and this caused the + * acquisition of the FILE lock + */ +FILE *qemu_log_trylock_context(void) G_GNUC_WARN_UNUSED_RESULT;
This is used just once, in qemu_log(). Could be inlined into qemu_log().
If you prefer to keep it as a function, you could make it static.
The intent was that some, but not all, places which currently use qemu_log_trylock() really ought to be including configured message prefix, and hence would need to call this method. No such updates of callers are done in this series though.
I wouldn't guess that this prints from the function name. Dunno, qemu_log_start_line()? Might want to pair it with a qemu_log_end_line() then.
Telling function name is less important if it's static.
Personally the inclusion of "log" in its filename is sufficiently suggestive. I'll rename it to qemu_log_trylock_with_context which is the name Richard originally requested.
diff --git a/util/log.c b/util/log.c index c44d66b5ce..2ce7286f31 100644 --- a/util/log.c +++ b/util/log.c @@ -127,13 +127,39 @@ static FILE *qemu_log_trylock_with_err(Error **errp)
Not this patch's fault, but here goes anyway:
static FILE *qemu_log_trylock_with_err(Error **errp) { FILE *logfile;
logfile = thread_file; if (!logfile) { if (log_per_thread) { g_autofree char *filename = g_strdup_printf(global_filename, log_thread_id()); logfile = fopen(filename, "w"); if (!logfile) { error_setg_errno(errp, errno, "Error opening logfile %s for thread %d", filename, log_thread_id()); return NULL; } thread_file = logfile; qemu_log_thread_cleanup_notifier.notify = qemu_log_thread_cleanup; qemu_thread_atexit_add(&qemu_log_thread_cleanup_notifier); } else { rcu_read_lock(); /* * FIXME: typeof_strip_qual, as used by qatomic_rcu_read, * does not work with pointers to undefined structures, * such as we have with struct _IO_FILE and musl libc. * Since all we want is a read of a pointer, cast to void**, * which does work with typeof_strip_qual. */ logfile = qatomic_rcu_read((void **)&global_file); if (!logfile) { rcu_read_unlock(); return NULL;
Fails without setting @errp.
Trivial to fix, I'll include a patch for that in next posting.
} } }
qemu_flockfile(logfile);
return logfile; }
+FILE *qemu_log_trylock_context(void) +{ + FILE *f = qemu_log_trylock();
This can fail, and if it does...
+ if (log_depth == 1 && message_with_timestamp) { + g_autofree const char *timestr = NULL; + g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); + timestr = g_date_time_format_iso8601(dt); + fprintf(f, "%s ", timestr);
... we crash here.
Opps, yes will fix. 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 :|
The error_printf_unless_qmp() will print to the monitor if the current one is HMP, if it is QMP nothing will be printed, otherwise stderr will be used. This scenario is easily handled by checking !monitor_cur_is_qmp() and then calling the error_printf() function. Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- ui/vnc.c | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/ui/vnc.c b/ui/vnc.c index a61a4f937d..a209c32f6d 100644 --- a/ui/vnc.c +++ b/ui/vnc.c @@ -3534,8 +3534,10 @@ int vnc_display_password(const char *id, const char *password) return -EINVAL; } if (vd->auth == VNC_AUTH_NONE) { - error_printf_unless_qmp("If you want use passwords please enable " - "password auth using '-vnc ${dpy},password'.\n"); + if (!monitor_cur_is_qmp()) { + error_printf("If you want to use passwords, please enable " + "password auth using '-vnc ${dpy},password'.\n"); + } return -EINVAL; } @@ -3574,9 +3576,11 @@ static void vnc_display_print_local_addr(VncDisplay *vd) qapi_free_SocketAddress(addr); return; } - error_printf_unless_qmp("VNC server running on %s:%s\n", - addr->u.inet.host, - addr->u.inet.port); + if (!monitor_cur_is_qmp()) { + error_printf("VNC server running on %s:%s\n", + addr->u.inet.host, + addr->u.inet.port); + } qapi_free_SocketAddress(addr); } -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
The error_printf_unless_qmp() will print to the monitor if the current one is HMP, if it is QMP nothing will be printed, otherwise stderr will be used.
This scenario is easily handled by checking !monitor_cur_is_qmp() and then calling the error_printf() function.
Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- ui/vnc.c | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-)
diff --git a/ui/vnc.c b/ui/vnc.c index a61a4f937d..a209c32f6d 100644 --- a/ui/vnc.c +++ b/ui/vnc.c @@ -3534,8 +3534,10 @@ int vnc_display_password(const char *id, const char *password) return -EINVAL; } if (vd->auth == VNC_AUTH_NONE) { - error_printf_unless_qmp("If you want use passwords please enable " - "password auth using '-vnc ${dpy},password'.\n"); + if (!monitor_cur_is_qmp()) { + error_printf("If you want to use passwords, please enable " + "password auth using '-vnc ${dpy},password'.\n"); + }
Let's mention the error message improvement in the commit message.
return -EINVAL; }
@@ -3574,9 +3576,11 @@ static void vnc_display_print_local_addr(VncDisplay *vd) qapi_free_SocketAddress(addr); return; } - error_printf_unless_qmp("VNC server running on %s:%s\n", - addr->u.inet.host, - addr->u.inet.port); + if (!monitor_cur_is_qmp()) { + error_printf("VNC server running on %s:%s\n", + addr->u.inet.host, + addr->u.inet.port); + } qapi_free_SocketAddress(addr); }
Daniel P. Berrangé <berrange@redhat.com> writes:
The error_printf_unless_qmp() will print to the monitor if the current one is HMP, if it is QMP nothing will be printed, otherwise stderr will be used.
This scenario is easily handled by checking !monitor_cur_is_qmp() and then calling the error_printf() function.
Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- ui/vnc.c | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-)
diff --git a/ui/vnc.c b/ui/vnc.c index a61a4f937d..a209c32f6d 100644 --- a/ui/vnc.c +++ b/ui/vnc.c @@ -3534,8 +3534,10 @@ int vnc_display_password(const char *id, const char *password) return -EINVAL; } if (vd->auth == VNC_AUTH_NONE) { - error_printf_unless_qmp("If you want use passwords please enable " - "password auth using '-vnc ${dpy},password'.\n"); + if (!monitor_cur_is_qmp()) { + error_printf("If you want to use passwords, please enable " + "password auth using '-vnc ${dpy},password'.\n"); + } return -EINVAL; }
@@ -3574,9 +3576,11 @@ static void vnc_display_print_local_addr(VncDisplay *vd) qapi_free_SocketAddress(addr); return; } - error_printf_unless_qmp("VNC server running on %s:%s\n", - addr->u.inet.host, - addr->u.inet.port); + if (!monitor_cur_is_qmp()) { + error_printf("VNC server running on %s:%s\n", + addr->u.inet.host, + addr->u.inet.port); + } qapi_free_SocketAddress(addr); }
These are the only remaining uses of monitor_cur_is_qmp() at the end of this series. Hmm. The first hunk is arguably sub-par error reporting. vnc_display_password() is called by qmp_set_password() and qmp_change_vnc_password(). Here's HMP: (qemu) set_password vnc 1234 If you want to use passwords, please enable password auth using '-vnc ${dpy},password'. Error: Could not set password QMP is even worse: {"execute": "set_password", "arguments": {"protocol": "vnc", "password": "1"}} {"error": {"class": "GenericError", "desc": "Could not set password"}} Better would be something like error_setg(errp, "VNC password authentication is disabled"); error_append_hint(errp, "To enable it, use ..."); where ... is the preferred way to enable it (not sure it's -vnc). HMP should then report Error: VNC password authentication is disabled To enable it, use ... and QMP {"error": {"class": "GenericError", "desc": "VNC password authentication is disabled"}} No need for monitor_cur_is_qmp() then. The second hunk applies in vnc_display_print_local_addr(), called by qemu_init() via qemu_init_displays(), vnc_init_func(), and vnc_display_open(). Can't be QMP; the monitor_cur_is_qmp() check could be dropped. Better: move the call up the call chain until "can't be QMP" is perfectly obvious. By the way, vnc_display_open() could be static.
These functions only had one caller which was easily converted to the normal error_printf() function. Remove them as they don't add sufficient value. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Markus Armbruster <armbru@redhat.com> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/monitor/monitor.h | 3 --- monitor/monitor.c | 24 ------------------------ stubs/error-printf.c | 5 ----- 3 files changed, 32 deletions(-) diff --git a/include/monitor/monitor.h b/include/monitor/monitor.h index c3740ec616..296690e1f1 100644 --- a/include/monitor/monitor.h +++ b/include/monitor/monitor.h @@ -59,7 +59,4 @@ void monitor_register_hmp(const char *name, bool info, void monitor_register_hmp_info_hrt(const char *name, HumanReadableText *(*handler)(Error **errp)); -int error_vprintf_unless_qmp(const char *fmt, va_list ap) G_GNUC_PRINTF(1, 0); -int error_printf_unless_qmp(const char *fmt, ...) G_GNUC_PRINTF(1, 2); - #endif /* MONITOR_H */ diff --git a/monitor/monitor.c b/monitor/monitor.c index dd2c45ded0..4d26cd9496 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -281,30 +281,6 @@ int error_vprintf(const char *fmt, va_list ap) return vfprintf(stderr, fmt, ap); } -int error_vprintf_unless_qmp(const char *fmt, va_list ap) -{ - Monitor *cur_mon = monitor_cur(); - - if (!cur_mon) { - return vfprintf(stderr, fmt, ap); - } - if (!monitor_cur_is_qmp()) { - return monitor_vprintf(cur_mon, fmt, ap); - } - return -1; -} - -int error_printf_unless_qmp(const char *fmt, ...) -{ - va_list ap; - int ret; - - va_start(ap, fmt); - ret = error_vprintf_unless_qmp(fmt, ap); - va_end(ap); - return ret; -} - static MonitorQAPIEventConf monitor_qapi_event_conf[QAPI_EVENT__MAX] = { /* Limit guest-triggerable events to 1 per second */ [QAPI_EVENT_RTC_CHANGE] = { 1000 * SCALE_MS }, diff --git a/stubs/error-printf.c b/stubs/error-printf.c index 0e326d8010..1afa0f62ca 100644 --- a/stubs/error-printf.c +++ b/stubs/error-printf.c @@ -16,8 +16,3 @@ int error_vprintf(const char *fmt, va_list ap) } return vfprintf(stderr, fmt, ap); } - -int error_vprintf_unless_qmp(const char *fmt, va_list ap) -{ - return error_vprintf(fmt, ap); -} -- 2.52.0
The monitor_vprintf() code will return -1 if either the monitor is NULL, or the monitor is QMP. The error_vprintf() code can take advantage of this to avoid having to duplicate the same checks, and instead simply look at the return value. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- monitor/monitor.c | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/monitor/monitor.c b/monitor/monitor.c index 4d26cd9496..627a59b23e 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -268,17 +268,19 @@ void monitor_printc(Monitor *mon, int c) monitor_printf(mon, "'"); } -/* - * Print to current monitor if we have one, else to stderr. - */ int error_vprintf(const char *fmt, va_list ap) { Monitor *cur_mon = monitor_cur(); - - if (cur_mon && !monitor_cur_is_qmp()) { - return monitor_vprintf(cur_mon, fmt, ap); + /* + * This will return -1 if 'cur_mon' is NULL, or is QMP. + * IOW this will only print if in HMP, otherwise we + * fallback to stderr for QMP / no-monitor scenarios. + */ + int ret = monitor_vprintf(cur_mon, fmt, ap); + if (ret == -1) { + ret = vfprintf(stderr, fmt, ap); } - return vfprintf(stderr, fmt, ap); + return ret; } static MonitorQAPIEventConf monitor_qapi_event_conf[QAPI_EVENT__MAX] = { -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
The monitor_vprintf() code will return -1 if either the monitor is NULL, or the monitor is QMP. The error_vprintf() code can take advantage of this to avoid having to duplicate the same checks, and instead simply look at the return value.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Reviewed-by: Markus Armbruster <armbru@redhat.com>
Daniel P. Berrangé <berrange@redhat.com> writes:
The monitor_vprintf() code will return -1 if either the monitor is NULL, or the monitor is QMP. The error_vprintf() code can take advantage of this to avoid having to duplicate the same checks, and instead simply look at the return value.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- monitor/monitor.c | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-)
diff --git a/monitor/monitor.c b/monitor/monitor.c index 4d26cd9496..627a59b23e 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -268,17 +268,19 @@ void monitor_printc(Monitor *mon, int c) monitor_printf(mon, "'"); }
-/* - * Print to current monitor if we have one, else to stderr. - */
Keep the comment, please.
int error_vprintf(const char *fmt, va_list ap) { Monitor *cur_mon = monitor_cur(); - - if (cur_mon && !monitor_cur_is_qmp()) { - return monitor_vprintf(cur_mon, fmt, ap); + /* + * This will return -1 if 'cur_mon' is NULL, or is QMP. + * IOW this will only print if in HMP, otherwise we + * fallback to stderr for QMP / no-monitor scenarios. + */ + int ret = monitor_vprintf(cur_mon, fmt, ap); + if (ret == -1) { + ret = vfprintf(stderr, fmt, ap); } - return vfprintf(stderr, fmt, ap); + return ret; }
static MonitorQAPIEventConf monitor_qapi_event_conf[QAPI_EVENT__MAX] = {
On Wed, Jan 14, 2026 at 12:34:14PM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
The monitor_vprintf() code will return -1 if either the monitor is NULL, or the monitor is QMP. The error_vprintf() code can take advantage of this to avoid having to duplicate the same checks, and instead simply look at the return value.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- monitor/monitor.c | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-)
diff --git a/monitor/monitor.c b/monitor/monitor.c index 4d26cd9496..627a59b23e 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -268,17 +268,19 @@ void monitor_printc(Monitor *mon, int c) monitor_printf(mon, "'"); }
-/* - * Print to current monitor if we have one, else to stderr. - */
Keep the comment, please.
I'll change it to say "...to the current human monitor..."
int error_vprintf(const char *fmt, va_list ap) { Monitor *cur_mon = monitor_cur(); - - if (cur_mon && !monitor_cur_is_qmp()) { - return monitor_vprintf(cur_mon, fmt, ap); + /* + * This will return -1 if 'cur_mon' is NULL, or is QMP. + * IOW this will only print if in HMP, otherwise we + * fallback to stderr for QMP / no-monitor scenarios. + */ + int ret = monitor_vprintf(cur_mon, fmt, ap); + if (ret == -1) { + ret = vfprintf(stderr, fmt, ap); } - return vfprintf(stderr, fmt, ap); + return ret; }
static MonitorQAPIEventConf monitor_qapi_event_conf[QAPI_EVENT__MAX] = {
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 :|
The current unit tests rely on monitor.o not being linked, such that the monitor stubs get linked instead. Since error_vprintf is in monitor.o this allows a stub error_vprintf impl to be used that calls g_test_message. This takes a different approach, with error_vprintf moving back to error-report.c such that it is always linked into the tests. The monitor_vprintf() stub is then changed to use g_test_message if QTEST_SILENT_ERRORS is set, otherwise it will return -1 and trigger error_vprintf to call vfprintf. The end result is functionally equivalent for the purposes of the unit tests. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Eric Blake <eblake@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- monitor/monitor.c | 15 --------------- stubs/error-printf.c | 18 ------------------ stubs/meson.build | 1 - stubs/monitor-core.c | 14 +++++++++++++- util/error-report.c | 15 +++++++++++++++ 5 files changed, 28 insertions(+), 35 deletions(-) delete mode 100644 stubs/error-printf.c diff --git a/monitor/monitor.c b/monitor/monitor.c index 627a59b23e..6dc5a7016d 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -268,21 +268,6 @@ void monitor_printc(Monitor *mon, int c) monitor_printf(mon, "'"); } -int error_vprintf(const char *fmt, va_list ap) -{ - Monitor *cur_mon = monitor_cur(); - /* - * This will return -1 if 'cur_mon' is NULL, or is QMP. - * IOW this will only print if in HMP, otherwise we - * fallback to stderr for QMP / no-monitor scenarios. - */ - int ret = monitor_vprintf(cur_mon, fmt, ap); - if (ret == -1) { - ret = vfprintf(stderr, fmt, ap); - } - return ret; -} - static MonitorQAPIEventConf monitor_qapi_event_conf[QAPI_EVENT__MAX] = { /* Limit guest-triggerable events to 1 per second */ [QAPI_EVENT_RTC_CHANGE] = { 1000 * SCALE_MS }, diff --git a/stubs/error-printf.c b/stubs/error-printf.c deleted file mode 100644 index 1afa0f62ca..0000000000 --- a/stubs/error-printf.c +++ /dev/null @@ -1,18 +0,0 @@ -#include "qemu/osdep.h" -#include "qemu/error-report.h" -#include "monitor/monitor.h" - -int error_vprintf(const char *fmt, va_list ap) -{ - int ret; - - if (g_test_initialized() && !g_test_subprocess() && - getenv("QTEST_SILENT_ERRORS")) { - char *msg = g_strdup_vprintf(fmt, ap); - g_test_message("%s", msg); - ret = strlen(msg); - g_free(msg); - return ret; - } - return vfprintf(stderr, fmt, ap); -} diff --git a/stubs/meson.build b/stubs/meson.build index 0b2778c568..3d77458a3f 100644 --- a/stubs/meson.build +++ b/stubs/meson.build @@ -3,7 +3,6 @@ # below, so that it is clear who needs the stubbed functionality. stub_ss.add(files('cpu-get-clock.c')) -stub_ss.add(files('error-printf.c')) stub_ss.add(files('fdset.c')) stub_ss.add(files('iothread-lock.c')) stub_ss.add(files('is-daemonized.c')) diff --git a/stubs/monitor-core.c b/stubs/monitor-core.c index 1894cdfe1f..a7c32297c9 100644 --- a/stubs/monitor-core.c +++ b/stubs/monitor-core.c @@ -18,5 +18,17 @@ void qapi_event_emit(QAPIEvent event, QDict *qdict) int monitor_vprintf(Monitor *mon, const char *fmt, va_list ap) { - abort(); + /* + * Pretend 'g_test_message' is our monitor console to + * stop the caller sending messages to stderr + */ + if (g_test_initialized() && !g_test_subprocess() && + getenv("QTEST_SILENT_ERRORS")) { + char *msg = g_strdup_vprintf(fmt, ap); + g_test_message("%s", msg); + size_t ret = strlen(msg); + g_free(msg); + return ret; + } + return -1; } diff --git a/util/error-report.c b/util/error-report.c index 1b17c11de1..b262ad01cb 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -29,6 +29,21 @@ bool message_with_timestamp; bool error_with_guestname; const char *error_guest_name; +int error_vprintf(const char *fmt, va_list ap) +{ + Monitor *cur_mon = monitor_cur(); + /* + * This will return -1 if 'cur_mon' is NULL, or is QMP. + * IOW this will only print if in HMP, otherwise we + * fallback to stderr for QMP / no-monitor scenarios. + */ + int ret = monitor_vprintf(cur_mon, fmt, ap); + if (ret == -1) { + ret = vfprintf(stderr, fmt, ap); + } + return ret; +} + int error_printf(const char *fmt, ...) { va_list ap; -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
The current unit tests rely on monitor.o not being linked, such that the monitor stubs get linked instead. Since error_vprintf is in monitor.o this allows a stub error_vprintf impl to be used that calls g_test_message.
This takes a different approach, with error_vprintf moving back to error-report.c such that it is always linked into the tests. The monitor_vprintf() stub is then changed to use g_test_message if QTEST_SILENT_ERRORS is set, otherwise it will return -1 and trigger error_vprintf to call vfprintf.
The end result is functionally equivalent for the purposes of the unit tests.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Eric Blake <eblake@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- monitor/monitor.c | 15 --------------- stubs/error-printf.c | 18 ------------------ stubs/meson.build | 1 - stubs/monitor-core.c | 14 +++++++++++++- util/error-report.c | 15 +++++++++++++++ 5 files changed, 28 insertions(+), 35 deletions(-) delete mode 100644 stubs/error-printf.c
diff --git a/monitor/monitor.c b/monitor/monitor.c index 627a59b23e..6dc5a7016d 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -268,21 +268,6 @@ void monitor_printc(Monitor *mon, int c) monitor_printf(mon, "'"); }
-int error_vprintf(const char *fmt, va_list ap) -{ - Monitor *cur_mon = monitor_cur(); - /* - * This will return -1 if 'cur_mon' is NULL, or is QMP. - * IOW this will only print if in HMP, otherwise we - * fallback to stderr for QMP / no-monitor scenarios. - */ - int ret = monitor_vprintf(cur_mon, fmt, ap); - if (ret == -1) { - ret = vfprintf(stderr, fmt, ap); - } - return ret; -} - static MonitorQAPIEventConf monitor_qapi_event_conf[QAPI_EVENT__MAX] = { /* Limit guest-triggerable events to 1 per second */ [QAPI_EVENT_RTC_CHANGE] = { 1000 * SCALE_MS }, diff --git a/stubs/error-printf.c b/stubs/error-printf.c deleted file mode 100644 index 1afa0f62ca..0000000000 --- a/stubs/error-printf.c +++ /dev/null @@ -1,18 +0,0 @@ -#include "qemu/osdep.h" -#include "qemu/error-report.h" -#include "monitor/monitor.h" - -int error_vprintf(const char *fmt, va_list ap) -{ - int ret; - - if (g_test_initialized() && !g_test_subprocess() && - getenv("QTEST_SILENT_ERRORS")) { - char *msg = g_strdup_vprintf(fmt, ap); - g_test_message("%s", msg); - ret = strlen(msg); - g_free(msg); - return ret; - } - return vfprintf(stderr, fmt, ap); -} diff --git a/stubs/meson.build b/stubs/meson.build index 0b2778c568..3d77458a3f 100644 --- a/stubs/meson.build +++ b/stubs/meson.build @@ -3,7 +3,6 @@ # below, so that it is clear who needs the stubbed functionality.
stub_ss.add(files('cpu-get-clock.c')) -stub_ss.add(files('error-printf.c')) stub_ss.add(files('fdset.c')) stub_ss.add(files('iothread-lock.c')) stub_ss.add(files('is-daemonized.c')) diff --git a/stubs/monitor-core.c b/stubs/monitor-core.c index 1894cdfe1f..a7c32297c9 100644 --- a/stubs/monitor-core.c +++ b/stubs/monitor-core.c @@ -18,5 +18,17 @@ void qapi_event_emit(QAPIEvent event, QDict *qdict)
int monitor_vprintf(Monitor *mon, const char *fmt, va_list ap) { - abort(); + /* + * Pretend 'g_test_message' is our monitor console to + * stop the caller sending messages to stderr + */ + if (g_test_initialized() && !g_test_subprocess() && + getenv("QTEST_SILENT_ERRORS")) { + char *msg = g_strdup_vprintf(fmt, ap); + g_test_message("%s", msg); + size_t ret = strlen(msg); + g_free(msg); + return ret; + } + return -1; } diff --git a/util/error-report.c b/util/error-report.c index 1b17c11de1..b262ad01cb 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -29,6 +29,21 @@ bool message_with_timestamp; bool error_with_guestname; const char *error_guest_name;
+int error_vprintf(const char *fmt, va_list ap) +{ + Monitor *cur_mon = monitor_cur(); + /* + * This will return -1 if 'cur_mon' is NULL, or is QMP. + * IOW this will only print if in HMP, otherwise we + * fallback to stderr for QMP / no-monitor scenarios. + */ + int ret = monitor_vprintf(cur_mon, fmt, ap); + if (ret == -1) { + ret = vfprintf(stderr, fmt, ap); + } + return ret; +} + int error_printf(const char *fmt, ...) { va_list ap;
Without stubs, no change in behavior. With both stubs, before the patch: monitor_vprintf() is not supposed to run, and aborts error_vprintf() calls g_test_message() for tests, else vfprintf() afterwards: monitor_vprintf() calls g_test_message() and succeeds in tests, else fails error_vprintf() calls monitor_printf(), and when it fails falls back to vfprintf(). Alright, error_vprintf() behaves the same as before. monitor_vprintf() no longer aborts. Hmm. What if we somehow acquire calls? In tests, they'll go to g_test_message(), which is fine, I guess. Outside tests, they'll fail. So does the non-stub version unless the current monitor is HMP. Also fine, I guess. Is it possible to link just one of the stubs?
On Tue, Jan 13, 2026 at 02:38:19PM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
The current unit tests rely on monitor.o not being linked, such that the monitor stubs get linked instead. Since error_vprintf is in monitor.o this allows a stub error_vprintf impl to be used that calls g_test_message.
This takes a different approach, with error_vprintf moving back to error-report.c such that it is always linked into the tests. The monitor_vprintf() stub is then changed to use g_test_message if QTEST_SILENT_ERRORS is set, otherwise it will return -1 and trigger error_vprintf to call vfprintf.
The end result is functionally equivalent for the purposes of the unit tests.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Eric Blake <eblake@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- monitor/monitor.c | 15 --------------- stubs/error-printf.c | 18 ------------------ stubs/meson.build | 1 - stubs/monitor-core.c | 14 +++++++++++++- util/error-report.c | 15 +++++++++++++++ 5 files changed, 28 insertions(+), 35 deletions(-) delete mode 100644 stubs/error-printf.c
diff --git a/monitor/monitor.c b/monitor/monitor.c index 627a59b23e..6dc5a7016d 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -268,21 +268,6 @@ void monitor_printc(Monitor *mon, int c) monitor_printf(mon, "'"); }
-int error_vprintf(const char *fmt, va_list ap) -{ - Monitor *cur_mon = monitor_cur(); - /* - * This will return -1 if 'cur_mon' is NULL, or is QMP. - * IOW this will only print if in HMP, otherwise we - * fallback to stderr for QMP / no-monitor scenarios. - */ - int ret = monitor_vprintf(cur_mon, fmt, ap); - if (ret == -1) { - ret = vfprintf(stderr, fmt, ap); - } - return ret; -} - static MonitorQAPIEventConf monitor_qapi_event_conf[QAPI_EVENT__MAX] = { /* Limit guest-triggerable events to 1 per second */ [QAPI_EVENT_RTC_CHANGE] = { 1000 * SCALE_MS }, diff --git a/stubs/error-printf.c b/stubs/error-printf.c deleted file mode 100644 index 1afa0f62ca..0000000000 --- a/stubs/error-printf.c +++ /dev/null @@ -1,18 +0,0 @@ -#include "qemu/osdep.h" -#include "qemu/error-report.h" -#include "monitor/monitor.h" - -int error_vprintf(const char *fmt, va_list ap) -{ - int ret; - - if (g_test_initialized() && !g_test_subprocess() && - getenv("QTEST_SILENT_ERRORS")) { - char *msg = g_strdup_vprintf(fmt, ap); - g_test_message("%s", msg); - ret = strlen(msg); - g_free(msg); - return ret; - } - return vfprintf(stderr, fmt, ap); -} diff --git a/stubs/meson.build b/stubs/meson.build index 0b2778c568..3d77458a3f 100644 --- a/stubs/meson.build +++ b/stubs/meson.build @@ -3,7 +3,6 @@ # below, so that it is clear who needs the stubbed functionality.
stub_ss.add(files('cpu-get-clock.c')) -stub_ss.add(files('error-printf.c')) stub_ss.add(files('fdset.c')) stub_ss.add(files('iothread-lock.c')) stub_ss.add(files('is-daemonized.c')) diff --git a/stubs/monitor-core.c b/stubs/monitor-core.c index 1894cdfe1f..a7c32297c9 100644 --- a/stubs/monitor-core.c +++ b/stubs/monitor-core.c @@ -18,5 +18,17 @@ void qapi_event_emit(QAPIEvent event, QDict *qdict)
int monitor_vprintf(Monitor *mon, const char *fmt, va_list ap) { - abort(); + /* + * Pretend 'g_test_message' is our monitor console to + * stop the caller sending messages to stderr + */ + if (g_test_initialized() && !g_test_subprocess() && + getenv("QTEST_SILENT_ERRORS")) { + char *msg = g_strdup_vprintf(fmt, ap); + g_test_message("%s", msg); + size_t ret = strlen(msg); + g_free(msg); + return ret; + } + return -1; } diff --git a/util/error-report.c b/util/error-report.c index 1b17c11de1..b262ad01cb 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -29,6 +29,21 @@ bool message_with_timestamp; bool error_with_guestname; const char *error_guest_name;
+int error_vprintf(const char *fmt, va_list ap) +{ + Monitor *cur_mon = monitor_cur(); + /* + * This will return -1 if 'cur_mon' is NULL, or is QMP. + * IOW this will only print if in HMP, otherwise we + * fallback to stderr for QMP / no-monitor scenarios. + */ + int ret = monitor_vprintf(cur_mon, fmt, ap); + if (ret == -1) { + ret = vfprintf(stderr, fmt, ap); + } + return ret; +} + int error_printf(const char *fmt, ...) { va_list ap;
Without stubs, no change in behavior.
With both stubs, before the patch:
monitor_vprintf() is not supposed to run, and aborts
error_vprintf() calls g_test_message() for tests, else vfprintf()
afterwards:
monitor_vprintf() calls g_test_message() and succeeds in tests, else fails
error_vprintf() calls monitor_printf(), and when it fails falls back to vfprintf().
Alright, error_vprintf() behaves the same as before.
monitor_vprintf() no longer aborts. Hmm. What if we somehow acquire calls? In tests, they'll go to g_test_message(), which is fine, I guess. Outside tests, they'll fail. So does the non-stub version unless the current monitor is HMP. Also fine, I guess.
Is it possible to link just one of the stubs?
There is only 1 stub after this patch - for monitor_vprintf(). error_vprintf() is never stubbed anymore. The interesting scenario outside there tests is the non-system emulator binaries. Those will not have the monitor code, so will get the monitor_vprintf stub. That will report g_test_initialized() == false, and so the stub will return -1. error_vprintf() will see this -1 return value and thus call to vfprintf(). So the behaviour is again the same as before this patch AFAICT for all linkage scenarios. 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 :|
Daniel P. Berrangé <berrange@redhat.com> writes:
On Tue, Jan 13, 2026 at 02:38:19PM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
The current unit tests rely on monitor.o not being linked, such that the monitor stubs get linked instead. Since error_vprintf is in monitor.o this allows a stub error_vprintf impl to be used that calls g_test_message.
This takes a different approach, with error_vprintf moving back to error-report.c such that it is always linked into the tests. The monitor_vprintf() stub is then changed to use g_test_message if QTEST_SILENT_ERRORS is set, otherwise it will return -1 and trigger error_vprintf to call vfprintf.
The end result is functionally equivalent for the purposes of the unit tests.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Eric Blake <eblake@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
[...]
Without stubs, no change in behavior.
With both stubs, before the patch:
monitor_vprintf() is not supposed to run, and aborts
error_vprintf() calls g_test_message() for tests, else vfprintf()
afterwards:
monitor_vprintf() calls g_test_message() and succeeds in tests, else fails
error_vprintf() calls monitor_printf(), and when it fails falls back to vfprintf().
Alright, error_vprintf() behaves the same as before.
monitor_vprintf() no longer aborts. Hmm. What if we somehow acquire calls? In tests, they'll go to g_test_message(), which is fine, I guess. Outside tests, they'll fail. So does the non-stub version unless the current monitor is HMP. Also fine, I guess.
Is it possible to link just one of the stubs?
There is only 1 stub after this patch - for monitor_vprintf(). error_vprintf() is never stubbed anymore.
The interesting scenario outside there tests is the non-system emulator binaries.
Those will not have the monitor code, so will get the monitor_vprintf stub. That will report g_test_initialized() == false, and so the stub will return -1. error_vprintf() will see this -1 return value and thus call to vfprintf().
So the behaviour is again the same as before this patch AFAICT for all linkage scenarios.
Thank you! Reviewed-by: Markus Armbruster <armbru@redhat.com>
Note that this is not simply the inverse of monitor_cur_is_qmp(), as both helpers require that monitor_cur() is first non-NULL. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/monitor/monitor.h | 1 + monitor/monitor.c | 10 ++++++++++ stubs/monitor-core.c | 6 ++++++ tests/unit/test-util-sockets.c | 1 + 4 files changed, 18 insertions(+) diff --git a/include/monitor/monitor.h b/include/monitor/monitor.h index 296690e1f1..9c71e6cf3c 100644 --- a/include/monitor/monitor.h +++ b/include/monitor/monitor.h @@ -16,6 +16,7 @@ extern QemuOptsList qemu_mon_opts; Monitor *monitor_cur(void); Monitor *monitor_set_cur(Coroutine *co, Monitor *mon); bool monitor_cur_is_qmp(void); +bool monitor_cur_is_hmp(void); void monitor_init_globals(void); void monitor_init_globals_core(void); diff --git a/monitor/monitor.c b/monitor/monitor.c index 6dc5a7016d..b81cc7d2ed 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -116,6 +116,16 @@ bool monitor_cur_is_qmp(void) return cur_mon && monitor_is_qmp(cur_mon); } +/** + * Is the current monitor, if any, a HMP monitor? + */ +bool monitor_cur_is_hmp(void) +{ + Monitor *cur_mon = monitor_cur(); + + return cur_mon && !monitor_is_qmp(cur_mon); +} + /** * Is @mon is using readline? * Note: not all HMP monitors use readline, e.g., gdbserver has a diff --git a/stubs/monitor-core.c b/stubs/monitor-core.c index a7c32297c9..674211f48f 100644 --- a/stubs/monitor-core.c +++ b/stubs/monitor-core.c @@ -7,6 +7,12 @@ Monitor *monitor_cur(void) return NULL; } +bool monitor_cur_is_hmp(void) +{ + /* since monitor_cur() above returns NULL, this can't be true */ + return false; +} + Monitor *monitor_set_cur(Coroutine *co, Monitor *mon) { return NULL; diff --git a/tests/unit/test-util-sockets.c b/tests/unit/test-util-sockets.c index ee66d727c3..4b7f408902 100644 --- a/tests/unit/test-util-sockets.c +++ b/tests/unit/test-util-sockets.c @@ -74,6 +74,7 @@ int monitor_get_fd(Monitor *mon, const char *fdname, Error **errp) Monitor *monitor_cur(void) { return cur_mon; } Monitor *monitor_set_cur(Coroutine *co, Monitor *mon) { abort(); } int monitor_vprintf(Monitor *mon, const char *fmt, va_list ap) { abort(); } +bool monitor_cur_is_hmp(void) { return false; } #ifndef _WIN32 static void test_socket_fd_pass_name_good(void) -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
Note that this is not simply the inverse of monitor_cur_is_qmp(), as both helpers require that monitor_cur() is first non-NULL.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/monitor/monitor.h | 1 + monitor/monitor.c | 10 ++++++++++ stubs/monitor-core.c | 6 ++++++ tests/unit/test-util-sockets.c | 1 + 4 files changed, 18 insertions(+)
diff --git a/include/monitor/monitor.h b/include/monitor/monitor.h index 296690e1f1..9c71e6cf3c 100644 --- a/include/monitor/monitor.h +++ b/include/monitor/monitor.h @@ -16,6 +16,7 @@ extern QemuOptsList qemu_mon_opts; Monitor *monitor_cur(void); Monitor *monitor_set_cur(Coroutine *co, Monitor *mon); bool monitor_cur_is_qmp(void); +bool monitor_cur_is_hmp(void);
void monitor_init_globals(void); void monitor_init_globals_core(void); diff --git a/monitor/monitor.c b/monitor/monitor.c index 6dc5a7016d..b81cc7d2ed 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -116,6 +116,16 @@ bool monitor_cur_is_qmp(void) return cur_mon && monitor_is_qmp(cur_mon); }
+/** + * Is the current monitor, if any, a HMP monitor?
"an HMP"? Not a native speaker...
+ */ +bool monitor_cur_is_hmp(void) +{ + Monitor *cur_mon = monitor_cur(); + + return cur_mon && !monitor_is_qmp(cur_mon); +} +
The only use at the end of this series looks like this: Monitor *cur = NULL; if (monitor_cur_is_hmp()) { cur = monitor_cur(); } else { // some stderr code } Meh. Could do Monitor *cur = monitor_cur(); if (monitor_cur_is_qmp(cur)) { cur = NULL; // some stderr code } Or with a helper returning the HMP monitor, we could have something like cur = monitor_cur_hmp(); if (!cur) { // some stderr code } Doesn't mirror monitor_cur_is_qmp() then. But I just pointed out in reply to PATCH 11 that we don't actually need monitor_cur_is_qmp()> Ideas, not demands.
/** * Is @mon is using readline? * Note: not all HMP monitors use readline, e.g., gdbserver has a diff --git a/stubs/monitor-core.c b/stubs/monitor-core.c index a7c32297c9..674211f48f 100644 --- a/stubs/monitor-core.c +++ b/stubs/monitor-core.c @@ -7,6 +7,12 @@ Monitor *monitor_cur(void) return NULL; }
+bool monitor_cur_is_hmp(void) +{ + /* since monitor_cur() above returns NULL, this can't be true */
Maybe /* We can't have a monitor, let alone an HMP monitor */ Up to you.
+ return false; +} + Monitor *monitor_set_cur(Coroutine *co, Monitor *mon) { return NULL; diff --git a/tests/unit/test-util-sockets.c b/tests/unit/test-util-sockets.c index ee66d727c3..4b7f408902 100644 --- a/tests/unit/test-util-sockets.c +++ b/tests/unit/test-util-sockets.c @@ -74,6 +74,7 @@ int monitor_get_fd(Monitor *mon, const char *fdname, Error **errp) Monitor *monitor_cur(void) { return cur_mon; } Monitor *monitor_set_cur(Coroutine *co, Monitor *mon) { abort(); } int monitor_vprintf(Monitor *mon, const char *fmt, va_list ap) { abort(); } +bool monitor_cur_is_hmp(void) { return false; }
Fine. abort() would also be fine. Matter of taste.
#ifndef _WIN32 static void test_socket_fd_pass_name_good(void)
On Tue, Jan 13, 2026 at 03:57:09PM +0100, Markus Armbruster wrote:
Daniel P. Berrangé <berrange@redhat.com> writes:
Note that this is not simply the inverse of monitor_cur_is_qmp(), as both helpers require that monitor_cur() is first non-NULL.
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/monitor/monitor.h | 1 + monitor/monitor.c | 10 ++++++++++ stubs/monitor-core.c | 6 ++++++ tests/unit/test-util-sockets.c | 1 + 4 files changed, 18 insertions(+)
diff --git a/include/monitor/monitor.h b/include/monitor/monitor.h index 296690e1f1..9c71e6cf3c 100644 --- a/include/monitor/monitor.h +++ b/include/monitor/monitor.h @@ -16,6 +16,7 @@ extern QemuOptsList qemu_mon_opts; Monitor *monitor_cur(void); Monitor *monitor_set_cur(Coroutine *co, Monitor *mon); bool monitor_cur_is_qmp(void); +bool monitor_cur_is_hmp(void);
void monitor_init_globals(void); void monitor_init_globals_core(void); diff --git a/monitor/monitor.c b/monitor/monitor.c index 6dc5a7016d..b81cc7d2ed 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -116,6 +116,16 @@ bool monitor_cur_is_qmp(void) return cur_mon && monitor_is_qmp(cur_mon); }
+/** + * Is the current monitor, if any, a HMP monitor?
"an HMP"? Not a native speaker...
Not that I know the rules either really, but I think it does sound better as "an" :-)
+ */ +bool monitor_cur_is_hmp(void) +{ + Monitor *cur_mon = monitor_cur(); + + return cur_mon && !monitor_is_qmp(cur_mon); +} +
The only use at the end of this series looks like this:
Monitor *cur = NULL;
if (monitor_cur_is_hmp()) { cur = monitor_cur(); } else { // some stderr code }
Meh. Could do
Monitor *cur = monitor_cur();
if (monitor_cur_is_qmp(cur)) { cur = NULL; // some stderr code }
Or with a helper returning the HMP monitor, we could have something like
cur = monitor_cur_hmp();
if (!cur) { // some stderr code }
Doesn't mirror monitor_cur_is_qmp() then. But I just pointed out in reply to PATCH 11 that we don't actually need monitor_cur_is_qmp()>
I'll do the middle option here. It is pointless churn to delete monitor_cur_is_qmp and then add monitor_cur_is_hmp or monitor_cur_hmp, so i'll just use monitor_cur_is_qmp
Ideas, not demands.
/** * Is @mon is using readline? * Note: not all HMP monitors use readline, e.g., gdbserver has a diff --git a/stubs/monitor-core.c b/stubs/monitor-core.c index a7c32297c9..674211f48f 100644 --- a/stubs/monitor-core.c +++ b/stubs/monitor-core.c @@ -7,6 +7,12 @@ Monitor *monitor_cur(void) return NULL; }
+bool monitor_cur_is_hmp(void) +{ + /* since monitor_cur() above returns NULL, this can't be true */
Maybe
/* We can't have a monitor, let alone an HMP monitor */
Sure.
diff --git a/tests/unit/test-util-sockets.c b/tests/unit/test-util-sockets.c index ee66d727c3..4b7f408902 100644 --- a/tests/unit/test-util-sockets.c +++ b/tests/unit/test-util-sockets.c @@ -74,6 +74,7 @@ int monitor_get_fd(Monitor *mon, const char *fdname, Error **errp) Monitor *monitor_cur(void) { return cur_mon; } Monitor *monitor_set_cur(Coroutine *co, Monitor *mon) { abort(); } int monitor_vprintf(Monitor *mon, const char *fmt, va_list ap) { abort(); } +bool monitor_cur_is_hmp(void) { return false; }
Fine. abort() would also be fine. Matter of taste.
I tested abort is ok here . 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 :|
The vreport() function will print to HMP if available, otherwise to stderr. In the event that vreport() is called during execution of a QMP command, it will print to stderr, but mistakenly omit the message prefixes (timestamp, guest name, program name). Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/error-report.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/util/error-report.c b/util/error-report.c index b262ad01cb..872158ad90 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -159,7 +159,7 @@ static void print_loc(void) int i; const char *const *argp; - if (!monitor_cur() && g_get_prgname()) { + if (!monitor_cur_is_hmp() && g_get_prgname()) { error_printf("%s:", g_get_prgname()); sep = " "; } @@ -203,14 +203,14 @@ static void vreport(report_type type, const char *fmt, va_list ap) { gchar *timestr; - if (message_with_timestamp && !monitor_cur()) { + if (message_with_timestamp && !monitor_cur_is_hmp()) { timestr = real_time_iso8601(); error_printf("%s ", timestr); g_free(timestr); } /* Only prepend guest name if -msg guest-name and -name guest=... are set */ - if (error_with_guestname && error_guest_name && !monitor_cur()) { + if (error_with_guestname && error_guest_name && !monitor_cur_is_hmp()) { error_printf("%s ", error_guest_name); } -- 2.52.0
On 1/9/26 04:03, Daniel P. Berrangé wrote:
The vreport() function will print to HMP if available, otherwise to stderr. In the event that vreport() is called during execution of a QMP command, it will print to stderr, but mistakenly omit the message prefixes (timestamp, guest name, program name).
Signed-off-by: Daniel P. Berrangé<berrange@redhat.com> --- util/error-report.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-)
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> r~
Daniel P. Berrangé <berrange@redhat.com> writes:
The vreport() function will print to HMP if available, otherwise to stderr. In the event that vreport() is called during execution of a QMP command, it will print to stderr, but mistakenly omit the message prefixes (timestamp, guest name, program name).
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/error-report.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-)
diff --git a/util/error-report.c b/util/error-report.c index b262ad01cb..872158ad90 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -159,7 +159,7 @@ static void print_loc(void) int i; const char *const *argp;
- if (!monitor_cur() && g_get_prgname()) { + if (!monitor_cur_is_hmp() && g_get_prgname()) { error_printf("%s:", g_get_prgname()); sep = " "; } @@ -203,14 +203,14 @@ static void vreport(report_type type, const char *fmt, va_list ap) { gchar *timestr;
- if (message_with_timestamp && !monitor_cur()) { + if (message_with_timestamp && !monitor_cur_is_hmp()) { timestr = real_time_iso8601(); error_printf("%s ", timestr); g_free(timestr); }
/* Only prepend guest name if -msg guest-name and -name guest=... are set */ - if (error_with_guestname && error_guest_name && !monitor_cur()) { + if (error_with_guestname && error_guest_name && !monitor_cur_is_hmp()) { error_printf("%s ", error_guest_name); }
Reviewed-by: Markus Armbruster <armbru@redhat.com>
Daniel P. Berrangé <berrange@redhat.com> writes:
The vreport() function will print to HMP if available, otherwise to stderr. In the event that vreport() is called during execution of a QMP command, it will print to stderr, but mistakenly omit the message prefixes (timestamp, guest name, program name).
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/error-report.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-)
diff --git a/util/error-report.c b/util/error-report.c index b262ad01cb..872158ad90 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -159,7 +159,7 @@ static void print_loc(void) /* * Print current location to current monitor if we have one, else to stderr.
This comment is now wrong. Obvious fix: "to current HMP monitor". Losely related: "[PATCH 0/3] Doc fixes around "current monitor" printing". */ static void print_loc(void) { const char *sep = "";
int i; const char *const *argp;
- if (!monitor_cur() && g_get_prgname()) { + if (!monitor_cur_is_hmp() && g_get_prgname()) { error_printf("%s:", g_get_prgname()); sep = " "; } @@ -203,14 +203,14 @@ static void vreport(report_type type, const char *fmt, va_list ap)
/* * Print a message to current monitor if we have one, else to stderr. Likewise. * @report_type is the type of message: error, warning or informational. * Format arguments like vsprintf(). The resulting message should be * a single phrase, with no newline or trailing punctuation. * Prepend the current location and append a newline. */ G_GNUC_PRINTF(2, 0) static void vreport(report_type type, const char *fmt, va_list ap)
{ gchar *timestr;
- if (message_with_timestamp && !monitor_cur()) { + if (message_with_timestamp && !monitor_cur_is_hmp()) { timestr = real_time_iso8601(); error_printf("%s ", timestr); g_free(timestr); }
/* Only prepend guest name if -msg guest-name and -name guest=... are set */ - if (error_with_guestname && error_guest_name && !monitor_cur()) { + if (error_with_guestname && error_guest_name && !monitor_cur_is_hmp()) { error_printf("%s ", error_guest_name); }
The monitor_cur_hmp() function will acquire/release mutex locks, which will trigger trace probes, which can in turn trigger qemu_log() calls. vreport() calls monitor_cur() multiple times through its execution both directly and indirectly via error_vprintf(). The result is that the prefix information printed by vreport() gets interleaved with qemu_log() output, when run outside the context of an HMP command dispatcher. This can be seen with: $ qemu-system-x86_64 \ -msg timestamp=on,guest-name=on \ -display none \ -object tls-creds-x509,id=f,dir=fish \ -name fish \ -d trace:qemu_mutex* 2025-09-10T16:30:42.514374Z qemu_mutex_unlock released mutex 0x560b0339b4c0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514400Z qemu_mutex_lock waiting on mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514402Z qemu_mutex_locked taken mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514404Z qemu_mutex_unlock released mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.516716Z qemu_mutex_lock waiting on mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:30:42.516723Z qemu_mutex_locked taken mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:30:42.516726Z qemu_mutex_unlock released mutex 0x560b03398560 (../monitor/monitor.c:96) 2025-09-10T16:30:42.516728Z qemu_mutex_lock waiting on mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842057Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842058Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842055Z 2025-09-10T16:31:04.842060Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842061Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842062Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842064Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842065Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842066Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) fish 2025-09-10T16:31:04.842068Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842069Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842070Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842072Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842097Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842099Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) qemu-system-x86_64:2025-09-10T16:31:04.842100Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842102Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842103Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842105Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842106Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842107Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) Unable to access credentials fish/ca-cert.pem: No such file or directory2025-09-10T16:31:04.842109Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842110Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842111Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) To avoid this interleaving (as well as reduce the huge number of mutex lock/unlock calls) we need to ensure that monitor_cur_is_hmp() is only called once at the start of vreport(), and if no HMP is present, no further monitor APIs can be called. This implies error_[v]printf() cannot be called from vreport(). Instead we must introduce error_[v]printf_mon() which accept a pre-acquired Monitor object. In some cases, however, fprintf can be called directly as output will never be directed to the monitor. $ qemu-system-x86_64 \ -msg timestamp=on,guest-name=on \ -display none \ -object tls-creds-x509,id=f,dir=fish \ -name fish \ -d trace:qemu_mutex* 2025-09-10T16:31:22.701691Z qemu_mutex_unlock released mutex 0x5626fd3b84c0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701728Z qemu_mutex_lock waiting on mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701730Z qemu_mutex_locked taken mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701732Z qemu_mutex_unlock released mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.703989Z qemu_mutex_lock waiting on mutex 0x5626fd3b5560 (../monitor/monitor.c:91) 2025-09-10T16:31:22.703996Z qemu_mutex_locked taken mutex 0x5626fd3b5560 (../monitor/monitor.c:91) 2025-09-10T16:31:22.703999Z qemu_mutex_unlock released mutex 0x5626fd3b5560 (../monitor/monitor.c:96) 2025-09-10T16:31:22.704000Z fish qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/error-report.c | 67 +++++++++++++++++++++++++++++++-------------- 1 file changed, 46 insertions(+), 21 deletions(-) diff --git a/util/error-report.c b/util/error-report.c index 872158ad90..14b170ca4c 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -29,9 +29,12 @@ bool message_with_timestamp; bool error_with_guestname; const char *error_guest_name; -int error_vprintf(const char *fmt, va_list ap) +/* + * Print to current monitor if we have one, else to stderr. + */ +static int G_GNUC_PRINTF(2, 0) +error_vprintf_mon(Monitor *cur_mon, const char *fmt, va_list ap) { - Monitor *cur_mon = monitor_cur(); /* * This will return -1 if 'cur_mon' is NULL, or is QMP. * IOW this will only print if in HMP, otherwise we @@ -44,13 +47,30 @@ int error_vprintf(const char *fmt, va_list ap) return ret; } +static int G_GNUC_PRINTF(2, 3) +error_printf_mon(Monitor *cur_mon, const char *fmt, ...) +{ + va_list ap; + int ret; + + va_start(ap, fmt); + ret = error_vprintf_mon(cur_mon, fmt, ap); + va_end(ap); + return ret; +} + +int error_vprintf(const char *fmt, va_list ap) +{ + return error_vprintf_mon(monitor_cur(), fmt, ap); +} + int error_printf(const char *fmt, ...) { va_list ap; int ret; va_start(ap, fmt); - ret = error_vprintf(fmt, ap); + ret = error_vprintf_mon(monitor_cur(), fmt, ap); va_end(ap); return ret; } @@ -153,34 +173,34 @@ void loc_set_file(const char *fname, int lno) /* * Print current location to current monitor if we have one, else to stderr. */ -static void print_loc(void) +static void print_loc(Monitor *cur) { const char *sep = ""; int i; const char *const *argp; - if (!monitor_cur_is_hmp() && g_get_prgname()) { - error_printf("%s:", g_get_prgname()); + if (!cur && g_get_prgname()) { + fprintf(stderr, "%s:", g_get_prgname()); sep = " "; } switch (cur_loc->kind) { case LOC_CMDLINE: argp = cur_loc->ptr; for (i = 0; i < cur_loc->num; i++) { - error_printf("%s%s", sep, argp[i]); + error_printf_mon(cur, "%s%s", sep, argp[i]); sep = " "; } - error_printf(": "); + error_printf_mon(cur, ": "); break; case LOC_FILE: - error_printf("%s:", (const char *)cur_loc->ptr); + error_printf_mon(cur, "%s:", (const char *)cur_loc->ptr); if (cur_loc->num) { - error_printf("%d:", cur_loc->num); + error_printf_mon(cur, "%d:", cur_loc->num); } - error_printf(" "); + error_printf_mon(cur, " "); break; default: - error_printf("%s", sep); + error_printf_mon(cur, "%s", sep); } } @@ -201,34 +221,39 @@ real_time_iso8601(void) G_GNUC_PRINTF(2, 0) static void vreport(report_type type, const char *fmt, va_list ap) { + Monitor *cur = NULL; gchar *timestr; - if (message_with_timestamp && !monitor_cur_is_hmp()) { + if (monitor_cur_is_hmp()) { + cur = monitor_cur(); + } + + if (message_with_timestamp && !cur) { timestr = real_time_iso8601(); - error_printf("%s ", timestr); + fprintf(stderr, "%s ", timestr); g_free(timestr); } /* Only prepend guest name if -msg guest-name and -name guest=... are set */ - if (error_with_guestname && error_guest_name && !monitor_cur_is_hmp()) { - error_printf("%s ", error_guest_name); + if (error_with_guestname && error_guest_name && !cur) { + fprintf(stderr, "%s ", error_guest_name); } - print_loc(); + print_loc(cur); switch (type) { case REPORT_TYPE_ERROR: break; case REPORT_TYPE_WARNING: - error_printf("warning: "); + error_printf_mon(cur, "warning: "); break; case REPORT_TYPE_INFO: - error_printf("info: "); + error_printf_mon(cur, "info: "); break; } - error_vprintf(fmt, ap); - error_printf("\n"); + error_vprintf_mon(cur, fmt, ap); + error_printf_mon(cur, "\n"); } /* -- 2.52.0
On 1/9/26 04:03, Daniel P. Berrangé wrote:
The monitor_cur_hmp() function will acquire/release mutex locks, which will trigger trace probes, which can in turn trigger qemu_log() calls. vreport() calls monitor_cur() multiple times through its execution both directly and indirectly via error_vprintf().
The result is that the prefix information printed by vreport() gets interleaved with qemu_log() output, when run outside the context of an HMP command dispatcher. This can be seen with:
$ qemu-system-x86_64 \ -msg timestamp=on,guest-name=on \ -display none \ -object tls-creds-x509,id=f,dir=fish \ -name fish \ -dtrace:qemu_mutex* 2025-09-10T16:30:42.514374Z qemu_mutex_unlock released mutex 0x560b0339b4c0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514400Z qemu_mutex_lock waiting on mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514402Z qemu_mutex_locked taken mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514404Z qemu_mutex_unlock released mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.516716Z qemu_mutex_lock waiting on mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:30:42.516723Z qemu_mutex_locked taken mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:30:42.516726Z qemu_mutex_unlock released mutex 0x560b03398560 (../monitor/monitor.c:96) 2025-09-10T16:30:42.516728Z qemu_mutex_lock waiting on mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842057Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842058Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842055Z 2025-09-10T16:31:04.842060Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842061Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842062Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842064Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842065Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842066Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) fish 2025-09-10T16:31:04.842068Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842069Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842070Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842072Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842097Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842099Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) qemu-system-x86_64:2025-09-10T16:31:04.842100Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842102Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842103Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842105Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842106Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842107Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) Unable to access credentials fish/ca-cert.pem: No such file ordirectory2025-09-10T16:31:04.842109Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842110Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842111Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96)
To avoid this interleaving (as well as reduce the huge number of mutex lock/unlock calls) we need to ensure that monitor_cur_is_hmp() is only called once at the start of vreport(), and if no HMP is present, no further monitor APIs can be called.
This implies error_[v]printf() cannot be called from vreport(). Instead we must introduce error_[v]printf_mon() which accept a pre-acquired Monitor object. In some cases, however, fprintf can be called directly as output will never be directed to the monitor.
$ qemu-system-x86_64 \ -msg timestamp=on,guest-name=on \ -display none \ -object tls-creds-x509,id=f,dir=fish \ -name fish \ -dtrace:qemu_mutex* 2025-09-10T16:31:22.701691Z qemu_mutex_unlock released mutex 0x5626fd3b84c0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701728Z qemu_mutex_lock waiting on mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701730Z qemu_mutex_locked taken mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701732Z qemu_mutex_unlock released mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.703989Z qemu_mutex_lock waiting on mutex 0x5626fd3b5560 (../monitor/monitor.c:91) 2025-09-10T16:31:22.703996Z qemu_mutex_locked taken mutex 0x5626fd3b5560 (../monitor/monitor.c:91) 2025-09-10T16:31:22.703999Z qemu_mutex_unlock released mutex 0x5626fd3b5560 (../monitor/monitor.c:96) 2025-09-10T16:31:22.704000Z fish qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory
Signed-off-by: Daniel P. Berrangé<berrange@redhat.com> --- util/error-report.c | 67 +++++++++++++++++++++++++++++++-------------- 1 file changed, 46 insertions(+), 21 deletions(-)
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> r~
Daniel P. Berrangé <berrange@redhat.com> writes:
The monitor_cur_hmp() function will acquire/release mutex locks, which will trigger trace probes, which can in turn trigger qemu_log() calls. vreport() calls monitor_cur() multiple times through its execution both directly and indirectly via error_vprintf().
The result is that the prefix information printed by vreport() gets interleaved with qemu_log() output, when run outside the context of an HMP command dispatcher. This can be seen with:
$ qemu-system-x86_64 \ -msg timestamp=on,guest-name=on \ -display none \ -object tls-creds-x509,id=f,dir=fish \ -name fish \ -d trace:qemu_mutex* 2025-09-10T16:30:42.514374Z qemu_mutex_unlock released mutex 0x560b0339b4c0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514400Z qemu_mutex_lock waiting on mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514402Z qemu_mutex_locked taken mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.514404Z qemu_mutex_unlock released mutex 0x560b033983e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:30:42.516716Z qemu_mutex_lock waiting on mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:30:42.516723Z qemu_mutex_locked taken mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:30:42.516726Z qemu_mutex_unlock released mutex 0x560b03398560 (../monitor/monitor.c:96) 2025-09-10T16:30:42.516728Z qemu_mutex_lock waiting on mutex 0x560b03398560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842057Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842058Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842055Z 2025-09-10T16:31:04.842060Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842061Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842062Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842064Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842065Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842066Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) fish 2025-09-10T16:31:04.842068Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842069Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842070Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842072Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842097Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842099Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) qemu-system-x86_64:2025-09-10T16:31:04.842100Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842102Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842103Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) 2025-09-10T16:31:04.842105Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842106Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842107Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96) Unable to access credentials fish/ca-cert.pem: No such file or directory2025-09-10T16:31:04.842109Z qemu_mutex_lock waiting on mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842110Z qemu_mutex_locked taken mutex 0x564f5e401560 (../monitor/monitor.c:91) 2025-09-10T16:31:04.842111Z qemu_mutex_unlock released mutex 0x564f5e401560 (../monitor/monitor.c:96)
To avoid this interleaving (as well as reduce the huge number of mutex lock/unlock calls) we need to ensure that monitor_cur_is_hmp() is only called once at the start of vreport(), and if no HMP is present, no further monitor APIs can be called.
This implies error_[v]printf() cannot be called from vreport(). Instead we must introduce error_[v]printf_mon() which accept a pre-acquired Monitor object. In some cases, however, fprintf can be called directly as output will never be directed to the monitor.
$ qemu-system-x86_64 \ -msg timestamp=on,guest-name=on \ -display none \ -object tls-creds-x509,id=f,dir=fish \ -name fish \ -d trace:qemu_mutex* 2025-09-10T16:31:22.701691Z qemu_mutex_unlock released mutex 0x5626fd3b84c0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701728Z qemu_mutex_lock waiting on mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701730Z qemu_mutex_locked taken mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.701732Z qemu_mutex_unlock released mutex 0x5626fd3b53e0 (/var/home/berrange/src/virt/qemu/include/qemu/lockable.h:56) 2025-09-10T16:31:22.703989Z qemu_mutex_lock waiting on mutex 0x5626fd3b5560 (../monitor/monitor.c:91) 2025-09-10T16:31:22.703996Z qemu_mutex_locked taken mutex 0x5626fd3b5560 (../monitor/monitor.c:91) 2025-09-10T16:31:22.703999Z qemu_mutex_unlock released mutex 0x5626fd3b5560 (../monitor/monitor.c:96) 2025-09-10T16:31:22.704000Z fish qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/error-report.c | 67 +++++++++++++++++++++++++++++++-------------- 1 file changed, 46 insertions(+), 21 deletions(-)
diff --git a/util/error-report.c b/util/error-report.c index 872158ad90..14b170ca4c 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -29,9 +29,12 @@ bool message_with_timestamp; bool error_with_guestname; const char *error_guest_name;
-int error_vprintf(const char *fmt, va_list ap) +/* + * Print to current monitor if we have one, else to stderr. + */
Wrong. Suggest "to current HMP monitor if we have one". Or drop the comment.
+static int G_GNUC_PRINTF(2, 0) +error_vprintf_mon(Monitor *cur_mon, const char *fmt, va_list ap)
Call the argument @hmp_mon?
{ - Monitor *cur_mon = monitor_cur(); /* * This will return -1 if 'cur_mon' is NULL, or is QMP. * IOW this will only print if in HMP, otherwise we @@ -44,13 +47,30 @@ int error_vprintf(const char *fmt, va_list ap) return ret; }
If error_vprintf_mon() deserves a function comment, then error_printf_mon() deserves one, too.
+static int G_GNUC_PRINTF(2, 3) +error_printf_mon(Monitor *cur_mon, const char *fmt, ...) +{ + va_list ap; + int ret; + + va_start(ap, fmt); + ret = error_vprintf_mon(cur_mon, fmt, ap); + va_end(ap); + return ret; +} + +int error_vprintf(const char *fmt, va_list ap) +{ + return error_vprintf_mon(monitor_cur(), fmt, ap); +} + int error_printf(const char *fmt, ...) { va_list ap; int ret;
va_start(ap, fmt); - ret = error_vprintf(fmt, ap); + ret = error_vprintf_mon(monitor_cur(), fmt, ap); va_end(ap); return ret; } @@ -153,34 +173,34 @@ void loc_set_file(const char *fname, int lno) /* * Print current location to current monitor if we have one, else to stderr.
Not this patch's fault: this comment is inaccurate. Fixed in my "[PATCH 0/3] Doc fixes around "current monitor" printing".
*/ -static void print_loc(void) +static void print_loc(Monitor *cur)
Call the argument @hmp_mon?
{ const char *sep = ""; int i; const char *const *argp;
- if (!monitor_cur_is_hmp() && g_get_prgname()) { - error_printf("%s:", g_get_prgname()); + if (!cur && g_get_prgname()) { + fprintf(stderr, "%s:", g_get_prgname()); sep = " "; } switch (cur_loc->kind) { case LOC_CMDLINE: argp = cur_loc->ptr; for (i = 0; i < cur_loc->num; i++) { - error_printf("%s%s", sep, argp[i]); + error_printf_mon(cur, "%s%s", sep, argp[i]); sep = " "; } - error_printf(": "); + error_printf_mon(cur, ": "); break; case LOC_FILE: - error_printf("%s:", (const char *)cur_loc->ptr); + error_printf_mon(cur, "%s:", (const char *)cur_loc->ptr); if (cur_loc->num) { - error_printf("%d:", cur_loc->num); + error_printf_mon(cur, "%d:", cur_loc->num); } - error_printf(" "); + error_printf_mon(cur, " "); break; default: - error_printf("%s", sep); + error_printf_mon(cur, "%s", sep); } }
@@ -201,34 +221,39 @@ real_time_iso8601(void) G_GNUC_PRINTF(2, 0) static void vreport(report_type type, const char *fmt, va_list ap) { + Monitor *cur = NULL; gchar *timestr;
- if (message_with_timestamp && !monitor_cur_is_hmp()) { + if (monitor_cur_is_hmp()) { + cur = monitor_cur(); + }
See my review of PATCH 15. Rename @cur to @hmp_mon?
+ + if (message_with_timestamp && !cur) { timestr = real_time_iso8601(); - error_printf("%s ", timestr); + fprintf(stderr, "%s ", timestr); g_free(timestr); }
/* Only prepend guest name if -msg guest-name and -name guest=... are set */ - if (error_with_guestname && error_guest_name && !monitor_cur_is_hmp()) { - error_printf("%s ", error_guest_name); + if (error_with_guestname && error_guest_name && !cur) { + fprintf(stderr, "%s ", error_guest_name); }
- print_loc(); + print_loc(cur);
switch (type) { case REPORT_TYPE_ERROR: break; case REPORT_TYPE_WARNING: - error_printf("warning: "); + error_printf_mon(cur, "warning: "); break; case REPORT_TYPE_INFO: - error_printf("info: "); + error_printf_mon(cur, "info: "); break; }
- error_vprintf(fmt, ap); - error_printf("\n"); + error_vprintf_mon(cur, fmt, ap); + error_printf_mon(cur, "\n"); }
/*
The vreport() function will optionally emit an prefix for error messages which is output to stderr incrementally. In the event that two vreport() calls execute concurrently, there is a risk that the prefix output will interleave. To address this it is required to take a lock on 'stderr' when outputting errors. Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/error-report.c | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/util/error-report.c b/util/error-report.c index 14b170ca4c..46ea9ededa 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -226,6 +226,8 @@ static void vreport(report_type type, const char *fmt, va_list ap) if (monitor_cur_is_hmp()) { cur = monitor_cur(); + } else { + qemu_flockfile(stderr); } if (message_with_timestamp && !cur) { @@ -254,6 +256,10 @@ static void vreport(report_type type, const char *fmt, va_list ap) error_vprintf_mon(cur, fmt, ap); error_printf_mon(cur, "\n"); + + if (!cur) { + qemu_funlockfile(stderr); + } } /* -- 2.52.0
Daniel P. Berrangé <berrange@redhat.com> writes:
The vreport() function will optionally emit an prefix for error messages which is output to stderr incrementally. In the event that two vreport() calls execute concurrently, there is a risk that the prefix output will interleave. To address this it is required to take a lock on 'stderr' when outputting errors.
Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Reported-by: Markus Armbruster <armbru@redhat.com> Reviewed-by: Markus Armbruster <armbru@redhat.com>
The error-report and log code both have a need to add prefixes to messages they are printing, with the current example being a timestamp. The format and configuration they use should be consistent, so providing a common helper will ensure this is always the case. Initially the helper only emits a timestamp, but future patches will expand this. This takes the liberty of assigning the new file to the same maintainer as the existing error-report.c file, given it will be extracting some functionality from the latter. While vreport() dynamically changes between reporting to the monitor vs stderr, depending on whether HMP is active or not, message prefixes are only ever used in the non-HMP case. Thus the helper API can take a FILE * object and not have to deal with the monitor at all. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- MAINTAINERS | 2 ++ include/qemu/message.h | 28 ++++++++++++++++++++++++++++ util/meson.build | 1 + util/message.c | 23 +++++++++++++++++++++++ 4 files changed, 54 insertions(+) create mode 100644 include/qemu/message.h create mode 100644 util/message.c diff --git a/MAINTAINERS b/MAINTAINERS index 9a55b649e8..4d43078fb3 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -3218,9 +3218,11 @@ M: Markus Armbruster <armbru@redhat.com> S: Supported F: include/qapi/error.h F: include/qemu/error-report.h +F: include/qemu/message.h F: qapi/error.json F: util/error.c F: util/error-report.c +F: util/message.c F: scripts/coccinelle/err-bad-newline.cocci F: scripts/coccinelle/error-use-after-free.cocci F: scripts/coccinelle/error_propagate_null.cocci diff --git a/include/qemu/message.h b/include/qemu/message.h new file mode 100644 index 0000000000..0a06421f77 --- /dev/null +++ b/include/qemu/message.h @@ -0,0 +1,28 @@ +/* SPDX-License-Identifier: GPL-2.0-or-later */ + +#ifndef QEMU_MESSAGE_H +#define QEMU_MESSAGE_H + +enum QMessageFormatFlags { + QMESSAGE_FORMAT_TIMESTAMP = (1 << 0), +}; + +/** + * qmessage_set_format: + * @flags: the message information to emit + * + * Select which pieces of information to + * emit for messages + */ +void qmessage_set_format(int flags); + +/** + * qmessage_context_print: + * @fp: file to emit the prefix on + * + * Emit a message prefix with the information selected by + * an earlier call to qmessage_set_format. + */ +void qmessage_context_print(FILE *fp); + +#endif /* QEMU_MESSAGE_H */ diff --git a/util/meson.build b/util/meson.build index 35029380a3..f5365e3b4f 100644 --- a/util/meson.build +++ b/util/meson.build @@ -40,6 +40,7 @@ util_ss.add(files('host-utils.c')) util_ss.add(files('bitmap.c', 'bitops.c')) util_ss.add(files('fifo8.c')) util_ss.add(files('cacheflush.c')) +util_ss.add(files('message.c')) util_ss.add(files('error.c', 'error-report.c')) util_ss.add(files('qemu-print.c')) util_ss.add(files('id.c')) diff --git a/util/message.c b/util/message.c new file mode 100644 index 0000000000..99a403f9d0 --- /dev/null +++ b/util/message.c @@ -0,0 +1,23 @@ +/* SPDX-License-Identifier: GPL-2.0-or-later */ + +#include "qemu/osdep.h" + +#include "qemu/message.h" +#include "monitor/monitor.h" + +static int message_format; + +void qmessage_set_format(int flags) +{ + message_format = flags; +} + +void qmessage_context_print(FILE *fp) +{ + if (message_format & QMESSAGE_FORMAT_TIMESTAMP) { + g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); + g_autofree char *timestr = g_date_time_format_iso8601(dt); + fputs(timestr, fp); + fputc(' ', fp); + } +} -- 2.52.0
Both the error-report and log APIs can optional emit a timestamp as a prefix on messages, with the '-msg timestamp=on' command line flag is set. Convert them to the new message API for formatting the context prefix, guaranteeing they will have matching behaviour going forward. There is no change in output format for either logs or errors with this conversion. There is a slight impact on logging code in that recording the timestamp is now potentially delayed by the need to acquire the logging mutex. Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/error-report.h | 1 - system/vl.c | 7 ++++++- tests/unit/test-error-report.c | 3 ++- util/error-report.c | 18 ++---------------- util/log.c | 8 +++----- 5 files changed, 13 insertions(+), 24 deletions(-) diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h index 3ae2357fda..c8000778ec 100644 --- a/include/qemu/error-report.h +++ b/include/qemu/error-report.h @@ -70,7 +70,6 @@ void error_init(const char *argv0); fmt, ##__VA_ARGS__); \ }) -extern bool message_with_timestamp; extern bool error_with_guestname; extern const char *error_guest_name; diff --git a/system/vl.c b/system/vl.c index 60bdd58548..75e2fd310d 100644 --- a/system/vl.c +++ b/system/vl.c @@ -26,6 +26,7 @@ #include "qemu/help-texts.h" #include "qemu/datadir.h" #include "qemu/units.h" +#include "qemu/message.h" #include "qemu/module.h" #include "qemu/target-info.h" #include "exec/cpu-common.h" @@ -818,8 +819,12 @@ static void realtime_init(void) static void configure_msg(QemuOpts *opts) { - message_with_timestamp = qemu_opt_get_bool(opts, "timestamp", false); + int flags = 0; + if (qemu_opt_get_bool(opts, "timestamp", false)) { + flags |= QMESSAGE_FORMAT_TIMESTAMP; + } error_with_guestname = qemu_opt_get_bool(opts, "guest-name", false); + qmessage_set_format(flags); } diff --git a/tests/unit/test-error-report.c b/tests/unit/test-error-report.c index a8532fc58f..9c63019694 100644 --- a/tests/unit/test-error-report.c +++ b/tests/unit/test-error-report.c @@ -12,6 +12,7 @@ #include "qemu/error-report.h" #include "qapi/error.h" +#include "qemu/message.h" static void test_error_report_simple(void) @@ -89,7 +90,7 @@ static void test_error_report_timestamp(void) { if (g_test_subprocess()) { - message_with_timestamp = true; + qmessage_set_format(QMESSAGE_FORMAT_TIMESTAMP); warn_report("warn"); error_report("err"); return; diff --git a/util/error-report.c b/util/error-report.c index 46ea9ededa..0c39857fc5 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -13,6 +13,7 @@ #include "qemu/osdep.h" #include "monitor/monitor.h" #include "qemu/error-report.h" +#include "qemu/message.h" /* * @report_type is the type of message: error, warning or @@ -24,8 +25,6 @@ typedef enum { REPORT_TYPE_INFO, } report_type; -/* Prepend timestamp to messages */ -bool message_with_timestamp; bool error_with_guestname; const char *error_guest_name; @@ -204,13 +203,6 @@ static void print_loc(Monitor *cur) } } -static char * -real_time_iso8601(void) -{ - g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); - return g_date_time_format_iso8601(dt); -} - /* * Print a message to current monitor if we have one, else to stderr. * @report_type is the type of message: error, warning or informational. @@ -222,18 +214,12 @@ G_GNUC_PRINTF(2, 0) static void vreport(report_type type, const char *fmt, va_list ap) { Monitor *cur = NULL; - gchar *timestr; if (monitor_cur_is_hmp()) { cur = monitor_cur(); } else { qemu_flockfile(stderr); - } - - if (message_with_timestamp && !cur) { - timestr = real_time_iso8601(); - fprintf(stderr, "%s ", timestr); - g_free(timestr); + qmessage_context_print(stderr); } /* Only prepend guest name if -msg guest-name and -name guest=... are set */ diff --git a/util/log.c b/util/log.c index 2ce7286f31..3b94c6541b 100644 --- a/util/log.c +++ b/util/log.c @@ -22,6 +22,7 @@ #include "qemu/range.h" #include "qemu/error-report.h" #include "qapi/error.h" +#include "qemu/message.h" #include "qemu/cutils.h" #include "trace/control.h" #include "qemu/thread.h" @@ -147,11 +148,8 @@ FILE *qemu_log_trylock(void) FILE *qemu_log_trylock_context(void) { FILE *f = qemu_log_trylock(); - if (log_depth == 1 && message_with_timestamp) { - g_autofree const char *timestr = NULL; - g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); - timestr = g_date_time_format_iso8601(dt); - fprintf(f, "%s ", timestr); + if (log_depth == 1) { + qmessage_context_print(f); } return f; } -- 2.52.0
The error_report function can include the guest name in any messages it prints. The qemu_log function has no equivalent behaviour. This introduces support for a "workload name" in the new messages API, which in the case of system emulators will be the guest name. The possibility of defining a workload name for other binaries is left as an exercise for the future. This change has no impact on the output of the error_report function, but will change the qemu_log function. This can be easily seen with the 'log' trace backend, and how it is now more closely matching error_report output. Before: # qemu-system-x86_64 -msg guest-name=on -name blah -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*' qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55b3af3fd870 dir=fish qcrypto_tls_creds_get_path TLS creds path creds=0x55b3af3fd870 filename=ca-cert.pem path=<none> blah qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory After: # qemu-system-x86_64 -msg guest-name=on -name blah -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*' blah qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55b3af3fd870 dir=fish blah qcrypto_tls_creds_get_path TLS creds path creds=0x55b3af3fd870 filename=ca-cert.pem path=<none> blah qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/error-report.h | 3 --- include/qemu/message.h | 10 ++++++++++ system/vl.c | 6 ++++-- util/error-report.c | 7 ------- util/message.c | 12 ++++++++++++ 5 files changed, 26 insertions(+), 12 deletions(-) diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h index c8000778ec..ffc305f828 100644 --- a/include/qemu/error-report.h +++ b/include/qemu/error-report.h @@ -70,7 +70,4 @@ void error_init(const char *argv0); fmt, ##__VA_ARGS__); \ }) -extern bool error_with_guestname; -extern const char *error_guest_name; - #endif diff --git a/include/qemu/message.h b/include/qemu/message.h index 0a06421f77..cfc3c92648 100644 --- a/include/qemu/message.h +++ b/include/qemu/message.h @@ -5,6 +5,7 @@ enum QMessageFormatFlags { QMESSAGE_FORMAT_TIMESTAMP = (1 << 0), + QMESSAGE_FORMAT_WORKLOAD_NAME = (1 << 1), }; /** @@ -16,6 +17,15 @@ enum QMessageFormatFlags { */ void qmessage_set_format(int flags); +/** + * qmessage_set_workload_name: + * @name: the name of the workload + * + * Set the workload name, which for a system emulator + * will be the guest VM name. + */ +void qmessage_set_workload_name(const char *name); + /** * qmessage_context_print: * @fp: file to emit the prefix on diff --git a/system/vl.c b/system/vl.c index 75e2fd310d..5f3b5436a6 100644 --- a/system/vl.c +++ b/system/vl.c @@ -823,7 +823,9 @@ static void configure_msg(QemuOpts *opts) if (qemu_opt_get_bool(opts, "timestamp", false)) { flags |= QMESSAGE_FORMAT_TIMESTAMP; } - error_with_guestname = qemu_opt_get_bool(opts, "guest-name", false); + if (qemu_opt_get_bool(opts, "guest-name", false)) { + flags |= QMESSAGE_FORMAT_WORKLOAD_NAME; + } qmessage_set_format(flags); } @@ -3526,7 +3528,7 @@ void qemu_init(int argc, char **argv) exit(1); } /* Capture guest name if -msg guest-name is used later */ - error_guest_name = qemu_opt_get(opts, "guest"); + qmessage_set_workload_name(qemu_opt_get(opts, "guest")); break; case QEMU_OPTION_prom_env: if (nb_prom_envs >= MAX_PROM_ENVS) { diff --git a/util/error-report.c b/util/error-report.c index 0c39857fc5..313c2d6055 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -25,8 +25,6 @@ typedef enum { REPORT_TYPE_INFO, } report_type; -bool error_with_guestname; -const char *error_guest_name; /* * Print to current monitor if we have one, else to stderr. @@ -222,11 +220,6 @@ static void vreport(report_type type, const char *fmt, va_list ap) qmessage_context_print(stderr); } - /* Only prepend guest name if -msg guest-name and -name guest=... are set */ - if (error_with_guestname && error_guest_name && !cur) { - fprintf(stderr, "%s ", error_guest_name); - } - print_loc(cur); switch (type) { diff --git a/util/message.c b/util/message.c index 99a403f9d0..fb2c947153 100644 --- a/util/message.c +++ b/util/message.c @@ -6,12 +6,18 @@ #include "monitor/monitor.h" static int message_format; +static char *message_workloadname; void qmessage_set_format(int flags) { message_format = flags; } +void qmessage_set_workload_name(const char *name) +{ + message_workloadname = g_strdup(name); +} + void qmessage_context_print(FILE *fp) { if (message_format & QMESSAGE_FORMAT_TIMESTAMP) { @@ -20,4 +26,10 @@ void qmessage_context_print(FILE *fp) fputs(timestr, fp); fputc(' ', fp); } + + if ((message_format & QMESSAGE_FORMAT_WORKLOAD_NAME) && + message_workloadname) { + fputs(message_workloadname, fp); + fputc(' ', fp); + } } -- 2.52.0
The error_report function can include the program name in any messages it prints. The qemu_log function has no equivalent behaviour. This introduces support for a "program name" in the new messages API, which will be included by default for all binaries. This change tweaks the output of the error_report function, adding a space between the program name and the location info. The qemu_log function will gain the program name. This can be easily seen with the 'log' trace backend, and how it is now more closely matching error_report output. Before: # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*' qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x5584e13937f0 dir=fish qcrypto_tls_creds_get_path TLS creds path creds=0x5584e13937f0 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: qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x5584e13937f0 dir=fish qemu-system-x86_64: qcrypto_tls_creds_get_path TLS creds path creds=0x5584e13937f0 filename=ca-cert.pem path=<none> qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory When adding this the '-msg program-name=on|off' option is introduced, so that the program name (which is enabled by default) can be supressed if desired. This could be useful if '-msg guest-name=on' is being used as a more informative identifier. Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/message.h | 1 + qemu-options.hx | 9 +++++++-- system/vl.c | 11 ++++++++++- tests/unit/test-error-report.c | 5 +++-- util/error-report.c | 4 ---- util/message.c | 10 +++++++++- 6 files changed, 30 insertions(+), 10 deletions(-) diff --git a/include/qemu/message.h b/include/qemu/message.h index cfc3c92648..b8518d06be 100644 --- a/include/qemu/message.h +++ b/include/qemu/message.h @@ -6,6 +6,7 @@ enum QMessageFormatFlags { QMESSAGE_FORMAT_TIMESTAMP = (1 << 0), QMESSAGE_FORMAT_WORKLOAD_NAME = (1 << 1), + QMESSAGE_FORMAT_PROGRAM_NAME = (1 << 2), }; /** diff --git a/qemu-options.hx b/qemu-options.hx index e8057fdcc9..e58b55d1f7 100644 --- a/qemu-options.hx +++ b/qemu-options.hx @@ -5515,13 +5515,15 @@ ERST DEF("msg", HAS_ARG, QEMU_OPTION_msg, "-msg [timestamp=on|off][,guest-name=on|off]\n" + " [,program-name=on|off]\n" " control error message format\n" " timestamp=on enables timestamps (default: off)\n" " guest-name=on enables guest name prefix but only if\n" - " -name guest option is set (default: off)\n", + " -name guest option is set (default: off)\n" + " program-name=off disables program name prefix (default: on)\n", QEMU_ARCH_ALL) SRST -``-msg [timestamp=on|off][,guest-name=on|off]`` +``-msg [timestamp=on|off][,guest-name=on|off][,program-name=on|off]`` Control error message format. ``timestamp=on|off`` @@ -5530,6 +5532,9 @@ SRST ``guest-name=on|off`` Prefix messages with guest name but only if -name guest option is set otherwise the option is ignored. Default is off. + + ``program-name=on|off`` + Prefix messages with the program name. Default is on. ERST DEF("dump-vmstate", HAS_ARG, QEMU_OPTION_dump_vmstate, diff --git a/system/vl.c b/system/vl.c index 5f3b5436a6..503b0dcc24 100644 --- a/system/vl.c +++ b/system/vl.c @@ -381,6 +381,12 @@ static QemuOptsList qemu_msg_opts = { .help = "Prepends guest name for error messages but only if " "-name guest is set otherwise option is ignored\n", }, + { + .name = "program-name", + .type = QEMU_OPT_BOOL, + .help = "Prepends program name for error messages (enabled " + "by default)\n", + }, { /* end of list */ } }, }; @@ -819,13 +825,16 @@ static void realtime_init(void) static void configure_msg(QemuOpts *opts) { - int flags = 0; + int flags = QMESSAGE_FORMAT_PROGRAM_NAME; if (qemu_opt_get_bool(opts, "timestamp", false)) { flags |= QMESSAGE_FORMAT_TIMESTAMP; } if (qemu_opt_get_bool(opts, "guest-name", false)) { flags |= QMESSAGE_FORMAT_WORKLOAD_NAME; } + if (!qemu_opt_get_bool(opts, "program-name", true)) { + flags &= ~QMESSAGE_FORMAT_PROGRAM_NAME; + } qmessage_set_format(flags); } diff --git a/tests/unit/test-error-report.c b/tests/unit/test-error-report.c index 9c63019694..714eafc51e 100644 --- a/tests/unit/test-error-report.c +++ b/tests/unit/test-error-report.c @@ -47,7 +47,7 @@ test_error_report_loc(void) g_test_trap_subprocess(NULL, 0, 0); g_test_trap_assert_passed(); g_test_trap_assert_stderr("\ -test-error-report:some-file.c:7717: test error1*\ +test-error-report: some-file.c:7717: test error1*\ test-error-report: test error2*\ "); } @@ -90,7 +90,8 @@ static void test_error_report_timestamp(void) { if (g_test_subprocess()) { - qmessage_set_format(QMESSAGE_FORMAT_TIMESTAMP); + qmessage_set_format(QMESSAGE_FORMAT_TIMESTAMP | + QMESSAGE_FORMAT_PROGRAM_NAME); warn_report("warn"); error_report("err"); return; diff --git a/util/error-report.c b/util/error-report.c index 313c2d6055..4c82d10a36 100644 --- a/util/error-report.c +++ b/util/error-report.c @@ -176,10 +176,6 @@ static void print_loc(Monitor *cur) int i; const char *const *argp; - if (!cur && g_get_prgname()) { - fprintf(stderr, "%s:", g_get_prgname()); - sep = " "; - } switch (cur_loc->kind) { case LOC_CMDLINE: argp = cur_loc->ptr; diff --git a/util/message.c b/util/message.c index fb2c947153..dd01bf7462 100644 --- a/util/message.c +++ b/util/message.c @@ -5,7 +5,7 @@ #include "qemu/message.h" #include "monitor/monitor.h" -static int message_format; +static int message_format = QMESSAGE_FORMAT_PROGRAM_NAME; static char *message_workloadname; void qmessage_set_format(int flags) @@ -32,4 +32,12 @@ void qmessage_context_print(FILE *fp) fputs(message_workloadname, fp); fputc(' ', fp); } + + if (message_format & QMESSAGE_FORMAT_PROGRAM_NAME) { + const char *pgnamestr = g_get_prgname(); + if (pgnamestr) { + fputs(pgnamestr, fp); + fputs(": ", fp); + } + } } -- 2.52.0
On 1/9/26 04:03, Daniel P. Berrangé wrote:
The error_report function can include the program name in any messages it prints. The qemu_log function has no equivalent behaviour.
This introduces support for a "program name" in the new messages API, which will be included by default for all binaries.
This change tweaks the output of the error_report function, adding a space between the program name and the location info. The qemu_log function will gain the program name. This can be easily seen with the 'log' trace backend, and how it is now more closely matching error_report output.
Before:
# qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*' qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x5584e13937f0 dir=fish qcrypto_tls_creds_get_path TLS creds path creds=0x5584e13937f0 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: qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x5584e13937f0 dir=fish qemu-system-x86_64: qcrypto_tls_creds_get_path TLS creds path creds=0x5584e13937f0 filename=ca-cert.pem path=<none> qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory
When adding this the '-msg program-name=on|off' option is introduced, so that the program name (which is enabled by default) can be supressed if desired. This could be useful if '-msg guest-name=on' is being used as a more informative identifier.
Signed-off-by: Daniel P. Berrangé<berrange@redhat.com> --- include/qemu/message.h | 1 + qemu-options.hx | 9 +++++++-- system/vl.c | 11 ++++++++++- tests/unit/test-error-report.c | 5 +++-- util/error-report.c | 4 ---- util/message.c | 10 +++++++++- 6 files changed, 30 insertions(+), 10 deletions(-)
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> r~
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 The '-msg thread-info=on|off' argument is introduced to allow this new default output to be supressed if desired. Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/message.h | 1 + qemu-options.hx | 10 +++++++--- storage-daemon/qemu-storage-daemon.c | 6 ++++++ system/vl.c | 17 +++++++++++++++-- tests/qemu-iotests/041 | 2 +- tests/qemu-iotests/common.filter | 2 +- util/message.c | 7 +++++++ 7 files changed, 38 insertions(+), 7 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/qemu-options.hx b/qemu-options.hx index e58b55d1f7..5c09fd8e36 100644 --- a/qemu-options.hx +++ b/qemu-options.hx @@ -5515,15 +5515,16 @@ ERST DEF("msg", HAS_ARG, QEMU_OPTION_msg, "-msg [timestamp=on|off][,guest-name=on|off]\n" - " [,program-name=on|off]\n" + " [,program-name=on|off][,thread-info=on|off]\n" " control error message format\n" " timestamp=on enables timestamps (default: off)\n" " guest-name=on enables guest name prefix but only if\n" " -name guest option is set (default: off)\n" - " program-name=off disables program name prefix (default: on)\n", + " program-name=off disables program name prefix (default: on)\n" + " thread-info=off disables thread ID and name prefix (default: on)\n", QEMU_ARCH_ALL) SRST -``-msg [timestamp=on|off][,guest-name=on|off][,program-name=on|off]`` +``-msg [timestamp=on|off][,guest-name=on|off][,program-name=on|off][,thread-info=on|off]`` Control error message format. ``timestamp=on|off`` @@ -5535,6 +5536,9 @@ SRST ``program-name=on|off`` Prefix messages with the program name. Default is on. + + ``guest-info=on|off`` + Prefix messages with the thread ID and name. Default is on. ERST DEF("dump-vmstate", HAS_ARG, QEMU_OPTION_dump_vmstate, 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 503b0dcc24..50209e6f4e 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; @@ -387,6 +391,12 @@ static QemuOptsList qemu_msg_opts = { .help = "Prepends program name for error messages (enabled " "by default)\n", }, + { + .name = "program-name", + .type = QEMU_OPT_BOOL, + .help = "Prepends current thread ID and name for error messages " + "(enabled by default)\n", + }, { /* end of list */ } }, }; @@ -822,10 +832,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; } @@ -835,6 +844,9 @@ static void configure_msg(QemuOpts *opts) if (!qemu_opt_get_bool(opts, "program-name", true)) { flags &= ~QMESSAGE_FORMAT_PROGRAM_NAME; } + if (!qemu_opt_get_bool(opts, "thread-info", true)) { + flags &= ~QMESSAGE_FORMAT_THREAD_INFO; + } qmessage_set_format(flags); } @@ -2903,6 +2915,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 26e6b45b04..c8cb2e860c 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 dd01bf7462..9bf640c8c4 100644 --- a/util/message.c +++ b/util/message.c @@ -40,4 +40,11 @@ void qmessage_context_print(FILE *fp) fputs(": ", fp); } } + + 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.52.0
On 1/9/26 04:03, Daniel P. Berrangé wrote:
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
The '-msg thread-info=on|off' argument is introduced to allow this new default output to be supressed if desired.
Signed-off-by: Daniel P. Berrangé<berrange@redhat.com> --- include/qemu/message.h | 1 + qemu-options.hx | 10 +++++++--- storage-daemon/qemu-storage-daemon.c | 6 ++++++ system/vl.c | 17 +++++++++++++++-- tests/qemu-iotests/041 | 2 +- tests/qemu-iotests/common.filter | 2 +- util/message.c | 7 +++++++ 7 files changed, 38 insertions(+), 7 deletions(-)
Reviewed-by: Richard Henderson <richard.henderson@linaro.org> r~
The message context can optionally include the guest name if the argument '-msg guest-name=on' is given. The formatting, however, does not look good if the guest name contains whitespace. Change the output to include square brackets to demarcate the name. Before: # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*' -msg guest-name=on -name "fish food" fish food qemu-system-x86_64: (1146846:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55657e94e690 dir=fish fish food qemu-system-x86_64: (1146846:main): qcrypto_tls_creds_get_path TLS creds path creds=0x55657e94e690 filename=ca-cert.pem path=<none> fish food qemu-system-x86_64: (1146846:main): 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*' -msg guest-name=on -name "fish food" [fish food] qemu-system-x86_64: (1144713:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x5604ada2c950 dir=fish [fish food] qemu-system-x86_64: (1144713:main): qcrypto_tls_creds_get_path TLS creds path creds=0x5604ada2c950 filename=ca-cert.pem path=<none> [fish food] qemu-system-x86_64: (1144713:main): Unable to access credentials fish/ca-cert.pem: No such file or directory Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/message.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/util/message.c b/util/message.c index 9bf640c8c4..73af8e8ca4 100644 --- a/util/message.c +++ b/util/message.c @@ -29,8 +29,9 @@ void qmessage_context_print(FILE *fp) if ((message_format & QMESSAGE_FORMAT_WORKLOAD_NAME) && message_workloadname) { + fputc('[', fp); fputs(message_workloadname, fp); - fputc(' ', fp); + fputs("] ", fp); } if (message_format & QMESSAGE_FORMAT_PROGRAM_NAME) { -- 2.52.0
participants (4)
-
Daniel P. Berrangé -
Markus Armbruster -
Paolo Bonzini -
Richard Henderson