@samitouri / QOSamiQemu / commits / 2eb00abcfe

util: fix interleaving of error & trace output

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 Reviewed-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>

Daniel P. Berrangé committed Sep 10, 2025 at 17:32 UTC 2eb00abcfebc3fa0a7c2915d1d29fa8fe0b88379
1 file changed +42 -21
util/error-report.c
+42 -21
@@ -32,9 +32,9 @@ const char *error_guest_name;
32 /*
33 * Print to the current human monitor if we have one, else to stderr.
34 */
35 -int error_vprintf(const char *fmt, va_list ap)
35 +static int G_GNUC_PRINTF(2, 0)
36 +error_vprintf_mon(Monitor *cur_mon, const char *fmt, va_list ap)
37 {
37 - Monitor *cur_mon = monitor_cur();
38 /*
39 * This will return -1 if 'cur_mon' is NULL, or is QMP.
40 * IOW this will only print if in HMP, otherwise we
@@ -47,13 +47,33 @@ int error_vprintf(const char *fmt, va_list ap)
47 return ret;
48 }
49
50 +/*
51 + * Print to the current human monitor if we have one, else to stderr.
52 + */
53 +static int G_GNUC_PRINTF(2, 3)
54 +error_printf_mon(Monitor *cur_mon, const char *fmt, ...)
55 +{
56 + va_list ap;
57 + int ret;
58 +
59 + va_start(ap, fmt);
60 + ret = error_vprintf_mon(cur_mon, fmt, ap);
61 + va_end(ap);
62 + return ret;
63 +}
64 +
65 +int error_vprintf(const char *fmt, va_list ap)
66 +{
67 + return error_vprintf_mon(monitor_cur(), fmt, ap);
68 +}
69 +
70 int error_printf(const char *fmt, ...)
71 {
72 va_list ap;
73 int ret;
74
75 va_start(ap, fmt);
56 - ret = error_vprintf(fmt, ap);
76 + ret = error_vprintf_mon(monitor_cur(), fmt, ap);
77 va_end(ap);
78 return ret;
79 }
@@ -156,34 +176,34 @@ void loc_set_file(const char *fname, int lno)
176 /*
177 * Print current location to current monitor if we have one, else to stderr.
178 */
159 -static void print_loc(void)
179 +static void print_loc(Monitor *cur)
180 {
181 const char *sep = "";
182 int i;
183 const char *const *argp;
184
165 - if (!monitor_cur() && g_get_prgname()) {
166 - error_printf("%s:", g_get_prgname());
185 + if (!cur && g_get_prgname()) {
186 + fprintf(stderr, "%s:", g_get_prgname());
187 sep = " ";
188 }
189 switch (cur_loc->kind) {
190 case LOC_CMDLINE:
191 argp = cur_loc->ptr;
192 for (i = 0; i < cur_loc->num; i++) {
173 - error_printf("%s%s", sep, argp[i]);
193 + error_printf_mon(cur, "%s%s", sep, argp[i]);
194 sep = " ";
195 }
176 - error_printf(": ");
196 + error_printf_mon(cur, ": ");
197 break;
198 case LOC_FILE:
179 - error_printf("%s:", (const char *)cur_loc->ptr);
199 + error_printf_mon(cur, "%s:", (const char *)cur_loc->ptr);
200 if (cur_loc->num) {
181 - error_printf("%d:", cur_loc->num);
201 + error_printf_mon(cur, "%d:", cur_loc->num);
202 }
183 - error_printf(" ");
203 + error_printf_mon(cur, " ");
204 break;
205 default:
186 - error_printf("%s", sep);
206 + error_printf_mon(cur, "%s", sep);
207 }
208 }
209
@@ -203,34 +223,35 @@ char *real_time_iso8601(void)
223 G_GNUC_PRINTF(2, 0)
224 static void vreport(report_type type, const char *fmt, va_list ap)
225 {
226 + Monitor *cur = monitor_cur();
227 gchar *timestr;
228
208 - if (message_with_timestamp && !monitor_cur()) {
229 + if (message_with_timestamp && !cur) {
230 timestr = real_time_iso8601();
210 - error_printf("%s ", timestr);
231 + fprintf(stderr, "%s ", timestr);
232 g_free(timestr);
233 }
234
235 /* Only prepend guest name if -msg guest-name and -name guest=... are set */
215 - if (error_with_guestname && error_guest_name && !monitor_cur()) {
216 - error_printf("%s ", error_guest_name);
236 + if (error_with_guestname && error_guest_name && !cur) {
237 + fprintf(stderr, "%s ", error_guest_name);
238 }
239
219 - print_loc();
240 + print_loc(cur);
241
242 switch (type) {
243 case REPORT_TYPE_ERROR:
244 break;
245 case REPORT_TYPE_WARNING:
225 - error_printf("warning: ");
246 + error_printf_mon(cur, "warning: ");
247 break;
248 case REPORT_TYPE_INFO:
228 - error_printf("info: ");
249 + error_printf_mon(cur, "info: ");
250 break;
251 }
252
232 - error_vprintf(fmt, ap);
233 - error_printf("\n");
253 + error_vprintf_mon(cur, fmt, ap);
254 + error_printf_mon(cur, "\n");
255 }
256
257 /*