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 b49a1a5fe3..92956e5d0f 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -70,6 +70,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_with_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..66f6dd5eec 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 unsigned int 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_with_context(void) +{ + FILE *f = qemu_log_trylock(); + if (f && 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_with_context(); if (f) { va_list ap; - - if (timestr) { - fprintf(f, "%s ", timestr); - } - va_start(ap, fmt); vfprintf(f, fmt, ap); va_end(ap); -- 2.53.0