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);