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 c5a5d30877..da54e1b1ce 100644 --- a/monitor/monitor.c +++ b/monitor/monitor.c @@ -704,18 +704,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.50.1

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> 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.50.1

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 974a3caad3..69dce3f302 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 @@ -696,7 +714,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.50.1

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 72da97829a..0893005919 100644 --- a/meson.build +++ b/meson.build @@ -2912,6 +2912,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..05c7ea4c00 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) { + 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..20165c6f95 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.50.1

Some code makes multiple qemu_log calls to incrementally emit a single message. Currently timestamps get prepended to all qemu_log calls, even those continuing a previous incomplete message. This changes the qemu_log so it skips adding a new line prefix, if the previous qemu_log call did NOT end with a newline. Fixes: 012842c07552 (log: make '-msg timestamp=on' apply to all qemu_log usage) Reported-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org> Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- util/log.c | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/util/log.c b/util/log.c index abdcb6b311..2642a55c59 100644 --- a/util/log.c +++ b/util/log.c @@ -143,6 +143,12 @@ void qemu_log_unlock(FILE *logfile) } } +/* + * 'true' if the previous log message lacked a trailing '\n', + * and thus the subsequent call must skip any prefix + */ +static __thread bool incomplete; + void qemu_log(const char *fmt, ...) { FILE *f; @@ -154,7 +160,7 @@ void qemu_log(const char *fmt, ...) * was emitted if we are delayed acquiring the * mutex */ - if (message_with_timestamp) { + if (message_with_timestamp && !incomplete) { g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); timestr = g_date_time_format_iso8601(dt); } @@ -170,6 +176,7 @@ void qemu_log(const char *fmt, ...) va_start(ap, fmt); vfprintf(f, fmt, ap); va_end(ap); + incomplete = fmt[strlen(fmt) - 1] != '\n'; qemu_log_unlock(f); } } -- 2.50.1

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 da54e1b1ce..03dbe5d131 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.50.1

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_SLENT_ERROS 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. 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 c00f4aac5a..e1e5dbfcbe 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 cef046e685..f58371f685 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.50.1

Note that this is not simply the inverse of monitor_cur_is_qmp(), as both helpers require that monitor_cur() is first non-NULL. 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 e1e5dbfcbe..27be5d7c73 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.50.1

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.50.1

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. 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 222c40d0d1..b6aa20dbae 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 { + 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) { + funlockfile(stderr); + } } /* -- 2.50.1

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 | 22 ++++++++++++++++++++++ 4 files changed, 53 insertions(+) create mode 100644 include/qemu/message.h create mode 100644 util/message.c diff --git a/MAINTAINERS b/MAINTAINERS index 24b71a4fc5..e128a9d3be 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -3173,9 +3173,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..643f10c06a --- /dev/null +++ b/util/message.c @@ -0,0 +1,22 @@ +/* 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); + fprintf(fp, "%s ", timestr); + } +} -- 2.50.1

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 | 11 +++++++++++ 5 files changed, 25 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 12bfdb3431..56829880f6 100644 --- a/system/vl.c +++ b/system/vl.c @@ -819,7 +819,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); } @@ -3521,7 +3523,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 c1146ba553..edb04585aa 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) { - error_printf_mon(NULL, "%s ", error_guest_name); - } - print_loc(cur); switch (type) { diff --git a/util/message.c b/util/message.c index 643f10c06a..a91c008e08 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) { @@ -19,4 +25,9 @@ void qmessage_context_print(FILE *fp) g_autofree char *timestr = g_date_time_format_iso8601(dt); fprintf(fp, "%s ", timestr); } + + if ((message_format & QMESSAGE_FORMAT_WORKLOAD_NAME) && + message_workloadname) { + fprintf(fp, "%s ", message_workloadname); + } } -- 2.50.1

The message context is now extended to be able to include the thread ID and thread name, after the program name. On Linux the thread ID will match the process TID visible in /proc, while on other platforms it will merely be an integer repr of the system thread object address/ID. This changes the output for both error_report and qemu_log, when running under the system emulators or the QEMU storage daemon. Other programs omit the thread information since they are largely single threaded, though potentially it would be useful to enable in all of them, given that the RCU thread will always get spawned by a constructor function. Before: # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*' qemu-system-x86_64: qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x560db818e080 dir=fish qemu-system-x86_64: qcrypto_tls_creds_get_path TLS creds path creds=0x560db818e080 filename=ca-cert.pem path=<none> qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory After: # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish -d 'trace:qcrypto*' qemu-system-x86_64: (772366:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x560db818e080 dir=fish qemu-system-x86_64: (772366:main): qcrypto_tls_creds_get_path TLS creds path creds=0x560db818e080 filename=ca-cert.pem path=<none> qemu-system-x86_64: (772366:main): Unable to access credentials fish/ca-cert.pem: No such file or directory Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/message.h | 1 + storage-daemon/qemu-storage-daemon.c | 6 ++++++ system/vl.c | 8 ++++++-- tests/qemu-iotests/041 | 2 +- tests/qemu-iotests/common.filter | 2 +- util/message.c | 7 +++++++ 6 files changed, 22 insertions(+), 4 deletions(-) diff --git a/include/qemu/message.h b/include/qemu/message.h index b8518d06be..2cc092c993 100644 --- a/include/qemu/message.h +++ b/include/qemu/message.h @@ -7,6 +7,7 @@ enum QMessageFormatFlags { QMESSAGE_FORMAT_TIMESTAMP = (1 << 0), QMESSAGE_FORMAT_WORKLOAD_NAME = (1 << 1), QMESSAGE_FORMAT_PROGRAM_NAME = (1 << 2), + QMESSAGE_FORMAT_THREAD_INFO = (1 << 3), }; /** diff --git a/storage-daemon/qemu-storage-daemon.c b/storage-daemon/qemu-storage-daemon.c index eb72561358..cc44ed7848 100644 --- a/storage-daemon/qemu-storage-daemon.c +++ b/storage-daemon/qemu-storage-daemon.c @@ -47,6 +47,7 @@ #include "qemu/cutils.h" #include "qemu/config-file.h" #include "qemu/error-report.h" +#include "qemu/message.h" #include "qemu/help_option.h" #include "qemu/job.h" #include "qemu/log.h" @@ -65,6 +66,10 @@ static const char *pid_file; static char *pid_file_realpath; static volatile bool exit_requested = false; +#define QMESSAGE_FORMAT_DEFAULT \ + (QMESSAGE_FORMAT_PROGRAM_NAME | \ + QMESSAGE_FORMAT_THREAD_INFO) + void qemu_system_killed(int signal, pid_t pid) { exit_requested = true; @@ -399,6 +404,7 @@ int main(int argc, char *argv[]) #endif error_init(argv[0]); + qmessage_set_format(QMESSAGE_FORMAT_DEFAULT); qemu_init_exec_dir(argv[0]); os_setup_signal_handling(); diff --git a/system/vl.c b/system/vl.c index 0ac1b11caf..fb8cc41876 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; @@ -812,10 +816,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; } @@ -2889,6 +2892,7 @@ void qemu_init(int argc, char **argv) module_call_init(MODULE_INIT_OPTS); error_init(argv[0]); + qmessage_set_format(QMESSAGE_FORMAT_DEFAULT); qemu_init_exec_dir(argv[0]); os_setup_limits(); diff --git a/tests/qemu-iotests/041 b/tests/qemu-iotests/041 index 8452845f44..dc2666afe7 100755 --- a/tests/qemu-iotests/041 +++ b/tests/qemu-iotests/041 @@ -1102,7 +1102,7 @@ class TestRepairQuorum(iotests.QMPTestCase): self.vm.shutdown() log = iotests.filter_qtest(self.vm.get_log()) log = re.sub(r'^Formatting.*\n', '', log) - log = re.sub(r'^%s: ' % os.path.basename(iotests.qemu_prog), '', log) + log = re.sub(r'^%s: \(\d+:\w+\): ' % os.path.basename(iotests.qemu_prog), '', log) self.assertEqual(log, "Can no longer replace 'img1' by 'repair0', because " + diff --git a/tests/qemu-iotests/common.filter b/tests/qemu-iotests/common.filter index 511a55b1e8..84f352d30b 100644 --- a/tests/qemu-iotests/common.filter +++ b/tests/qemu-iotests/common.filter @@ -81,7 +81,7 @@ _filter_qemu_io() # replace occurrences of QEMU_PROG with "qemu" _filter_qemu() { - gsed -e "s#\\(^\\|(qemu) \\)$(basename $QEMU_PROG):#\1QEMU_PROG:#" \ + gsed -e "s#\\(^\\|(qemu) \\)$(basename $QEMU_PROG): ([0-9]\+:[-_a-zA-Z]\+):#\1QEMU_PROG:#" \ -e 's#^QEMU [0-9]\+\.[0-9]\+\.[0-9]\+ monitor#QEMU X.Y.Z monitor#' \ -e $'s#\r##' # QEMU monitor uses \r\n line endings } diff --git a/util/message.c b/util/message.c index 1db9254733..814ca0316e 100644 --- a/util/message.c +++ b/util/message.c @@ -37,4 +37,11 @@ void qmessage_context_print(FILE *fp) fprintf(fp, "%s: ", pgnamestr); } } + + if (message_format & QMESSAGE_FORMAT_THREAD_INFO) { + int thid = qemu_get_thread_id(); + const char *thname = qemu_thread_get_name(); + + fprintf(fp, "(%d:%s): ", thid, thname); + } } -- 2.50.1

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 | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/util/message.c b/util/message.c index 814ca0316e..7d94b9d970 100644 --- a/util/message.c +++ b/util/message.c @@ -28,7 +28,7 @@ void qmessage_context_print(FILE *fp) if ((message_format & QMESSAGE_FORMAT_WORKLOAD_NAME) && message_workloadname) { - fprintf(fp, "%s ", message_workloadname); + fprintf(fp, "[%s] ", message_workloadname); } if (message_format & QMESSAGE_FORMAT_PROGRAM_NAME) { -- 2.50.1