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 :|
© 2016 - 2026 Red Hat, Inc.