There is a gotcha with qemu_log() usage in a threaded process.
If fragments of a log message are output via qemu_log() it is
possible for messages from two threads to get mixed up. To
prevent this qemu_log_trylock() should be used, along with
fprintf(f) calls.

This is a subtle problem that needs to be explained in the
API docs to ensure correct usage.

Reported-by: Markus Armbruster <armbru@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 include/qemu/log-for-trace.h | 17 ++++++++++++++++-
 include/qemu/log.h           | 31 +++++++++++++++++++++++++++++++
 rust/util/src/log.rs         |  6 ++++++
 3 files changed, 53 insertions(+), 1 deletion(-)

diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
index f3a8791f1d..6861a1a4b7 100644
--- a/include/qemu/log-for-trace.h
+++ b/include/qemu/log-for-trace.h
@@ -29,7 +29,22 @@ static inline bool qemu_loglevel_mask(int mask)
     return (qemu_loglevel & mask) != 0;
 }
 
-/* main logging function */
+/**
+ * qemu_log: report a log message
+ * @fmt: the format string for the message
+ * @...: the format string arguments
+ *
+ * This will emit a log message to the current output stream.
+ *
+ * The @fmt string should normally represent a complete line
+ * of text, and thus end with a newline character.
+ *
+ * While it is possible to incrementally output fragments of
+ * a complete line using qemu_log, this is inefficient and
+ * races with other threads. For outputting fragments it is
+ * strongly preferred to use the qemu_log_trylock() method
+ * combined with fprintf().
+ */
 void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
 
 #endif
diff --git a/include/qemu/log.h b/include/qemu/log.h
index 7effba4da4..e9d3c6806b 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -41,7 +41,38 @@ bool qemu_log_separate(void);
 
 /* Lock/unlock output. */
 
+/**
+ * Acquires a lock on the current log output stream.
+ * The returned FILE object should be used with the
+ * fprintf() function to output the log message, and
+ * then qemu_log_unlock() called to release the lock.
+ *
+ * The primary use case is to be able to incrementally
+ * output fragments of a complete log message in an
+ * efficient and race free manner.
+ *
+ * The simpler qemu_log() method must only be used
+ * to output complete log messages.
+ *
+ * A typical usage pattern would be
+ *
+ *    FILE *f = qemu_log_trylock()
+ *
+ *    fprintf(f, "Something ");
+ *    fprintf(f, "Something ");
+ *    fprintf(f, "Something ");
+ *    fprintf(f, "The end\n");
+ *
+ *    qemu_log_unlock(f);
+ *
+ * Returns: the current FILE if available, NULL on error
+ */
 FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT;
+
+/**
+ * Releases the lock on the log output, previously
+ * acquired by qemu_log_trylock().
+ */
 void qemu_log_unlock(FILE *fd);
 
 /* Logging functions: */
diff --git a/rust/util/src/log.rs b/rust/util/src/log.rs
index 0a4bc4249a..6a3a30d8d8 100644
--- a/rust/util/src/log.rs
+++ b/rust/util/src/log.rs
@@ -134,6 +134,12 @@ fn drop(&mut self) {
 ///     "Address 0x{:x} out of range",
 ///     error_address,
 /// );
+///
+/// The `log_mask_ln` macro should only be used for emitting complete
+/// log messages. Where it is required to incrementally output string
+/// fragments to construct a complete message, `LogGuard::new()` should
+/// be directly used in combination with `writeln()` to avoid output
+/// races with other QEMU threads.
 /// ```
 #[macro_export]
 macro_rules! log_mask_ln {
-- 
2.52.0

Daniel P. Berrangé <berrange@redhat.com> writes:

> There is a gotcha with qemu_log() usage in a threaded process.
> If fragments of a log message are output via qemu_log() it is
> possible for messages from two threads to get mixed up. To
> prevent this qemu_log_trylock() should be used, along with
> fprintf(f) calls.
>
> This is a subtle problem that needs to be explained in the
> API docs to ensure correct usage.
>
> Reported-by: Markus Armbruster <armbru@redhat.com>
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  include/qemu/log-for-trace.h | 17 ++++++++++++++++-
>  include/qemu/log.h           | 31 +++++++++++++++++++++++++++++++
>  rust/util/src/log.rs         |  6 ++++++
>  3 files changed, 53 insertions(+), 1 deletion(-)
>
> diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
> index f3a8791f1d..6861a1a4b7 100644
> --- a/include/qemu/log-for-trace.h
> +++ b/include/qemu/log-for-trace.h
> @@ -29,7 +29,22 @@ static inline bool qemu_loglevel_mask(int mask)
>      return (qemu_loglevel & mask) != 0;
>  }
>  
> -/* main logging function */
> +/**
> + * qemu_log: report a log message
> + * @fmt: the format string for the message
> + * @...: the format string arguments
> + *
> + * This will emit a log message to the current output stream.
> + *
> + * The @fmt string should normally represent a complete line
> + * of text, and thus end with a newline character.

Note for later: "should normally".

> + *
> + * While it is possible to incrementally output fragments of
> + * a complete line using qemu_log, this is inefficient and
> + * races with other threads. For outputting fragments it is
> + * strongly preferred to use the qemu_log_trylock() method
> + * combined with fprintf().
> + */
>  void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
>  
>  #endif
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index 7effba4da4..e9d3c6806b 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -41,7 +41,38 @@ bool qemu_log_separate(void);
>  
>  /* Lock/unlock output. */
>  
> +/**
> + * Acquires a lock on the current log output stream.
> + * The returned FILE object should be used with the
> + * fprintf() function to output the log message, and
> + * then qemu_log_unlock() called to release the lock.
> + *
> + * The primary use case is to be able to incrementally
> + * output fragments of a complete log message in an
> + * efficient and race free manner.
> + *
> + * The simpler qemu_log() method must only be used
> + * to output complete log messages.

"must".

> + *
> + * A typical usage pattern would be
> + *
> + *    FILE *f = qemu_log_trylock()
> + *
> + *    fprintf(f, "Something ");
> + *    fprintf(f, "Something ");
> + *    fprintf(f, "Something ");
> + *    fprintf(f, "The end\n");
> + *
> + *    qemu_log_unlock(f);
> + *
> + * Returns: the current FILE if available, NULL on error
> + */
>  FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT;
> +
> +/**
> + * Releases the lock on the log output, previously
> + * acquired by qemu_log_trylock().
> + */
>  void qemu_log_unlock(FILE *fd);
>  
>  /* Logging functions: */
> diff --git a/rust/util/src/log.rs b/rust/util/src/log.rs
> index 0a4bc4249a..6a3a30d8d8 100644
> --- a/rust/util/src/log.rs
> +++ b/rust/util/src/log.rs
> @@ -134,6 +134,12 @@ fn drop(&mut self) {
>  ///     "Address 0x{:x} out of range",
>  ///     error_address,
>  /// );
> +///
> +/// The `log_mask_ln` macro should only be used for emitting complete

"should only".

> +/// log messages. Where it is required to incrementally output string
> +/// fragments to construct a complete message, `LogGuard::new()` should
> +/// be directly used in combination with `writeln()` to avoid output
> +/// races with other QEMU threads.
>  /// ```
>  #[macro_export]
>  macro_rules! log_mask_ln {

"Should normally" suggests there are exceptions.

"Should only" does not.

"Must" is a bit stronger still.

Which of the three do we want?

On Tue, Jan 13, 2026 at 10:59:49AM +0100, Markus Armbruster wrote:
> Daniel P. Berrangé <berrange@redhat.com> writes:
> 
> > There is a gotcha with qemu_log() usage in a threaded process.
> > If fragments of a log message are output via qemu_log() it is
> > possible for messages from two threads to get mixed up. To
> > prevent this qemu_log_trylock() should be used, along with
> > fprintf(f) calls.
> >
> > This is a subtle problem that needs to be explained in the
> > API docs to ensure correct usage.
> >
> > Reported-by: Markus Armbruster <armbru@redhat.com>
> > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > ---
> >  include/qemu/log-for-trace.h | 17 ++++++++++++++++-
> >  include/qemu/log.h           | 31 +++++++++++++++++++++++++++++++
> >  rust/util/src/log.rs         |  6 ++++++
> >  3 files changed, 53 insertions(+), 1 deletion(-)
> >
> > diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
> > index f3a8791f1d..6861a1a4b7 100644
> > --- a/include/qemu/log-for-trace.h
> > +++ b/include/qemu/log-for-trace.h
> > @@ -29,7 +29,22 @@ static inline bool qemu_loglevel_mask(int mask)
> >      return (qemu_loglevel & mask) != 0;
> >  }
> >  
> > -/* main logging function */
> > +/**
> > + * qemu_log: report a log message
> > + * @fmt: the format string for the message
> > + * @...: the format string arguments
> > + *
> > + * This will emit a log message to the current output stream.
> > + *
> > + * The @fmt string should normally represent a complete line
> > + * of text, and thus end with a newline character.
> 
> Note for later: "should normally".
> 
> > + *
> > + * While it is possible to incrementally output fragments of
> > + * a complete line using qemu_log, this is inefficient and
> > + * races with other threads. For outputting fragments it is
> > + * strongly preferred to use the qemu_log_trylock() method
> > + * combined with fprintf().
> > + */
> >  void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
> >  
> >  #endif
> > diff --git a/include/qemu/log.h b/include/qemu/log.h
> > index 7effba4da4..e9d3c6806b 100644
> > --- a/include/qemu/log.h
> > +++ b/include/qemu/log.h
> > @@ -41,7 +41,38 @@ bool qemu_log_separate(void);
> >  
> >  /* Lock/unlock output. */
> >  
> > +/**
> > + * Acquires a lock on the current log output stream.
> > + * The returned FILE object should be used with the
> > + * fprintf() function to output the log message, and
> > + * then qemu_log_unlock() called to release the lock.
> > + *
> > + * The primary use case is to be able to incrementally
> > + * output fragments of a complete log message in an
> > + * efficient and race free manner.
> > + *
> > + * The simpler qemu_log() method must only be used
> > + * to output complete log messages.
> 
> "must".
> 
> > + *
> > + * A typical usage pattern would be
> > + *
> > + *    FILE *f = qemu_log_trylock()
> > + *
> > + *    fprintf(f, "Something ");
> > + *    fprintf(f, "Something ");
> > + *    fprintf(f, "Something ");
> > + *    fprintf(f, "The end\n");
> > + *
> > + *    qemu_log_unlock(f);
> > + *
> > + * Returns: the current FILE if available, NULL on error
> > + */
> >  FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT;
> > +
> > +/**
> > + * Releases the lock on the log output, previously
> > + * acquired by qemu_log_trylock().
> > + */
> >  void qemu_log_unlock(FILE *fd);
> >  
> >  /* Logging functions: */
> > diff --git a/rust/util/src/log.rs b/rust/util/src/log.rs
> > index 0a4bc4249a..6a3a30d8d8 100644
> > --- a/rust/util/src/log.rs
> > +++ b/rust/util/src/log.rs
> > @@ -134,6 +134,12 @@ fn drop(&mut self) {
> >  ///     "Address 0x{:x} out of range",
> >  ///     error_address,
> >  /// );
> > +///
> > +/// The `log_mask_ln` macro should only be used for emitting complete
> 
> "should only".
> 
> > +/// log messages. Where it is required to incrementally output string
> > +/// fragments to construct a complete message, `LogGuard::new()` should
> > +/// be directly used in combination with `writeln()` to avoid output
> > +/// races with other QEMU threads.
> >  /// ```
> >  #[macro_export]
> >  macro_rules! log_mask_ln {
> 
> "Should normally" suggests there are exceptions.
> 
> "Should only" does not.
> 
> "Must" is a bit stronger still.
> 
> Which of the three do we want?

The "Should" usage was reflecting the reality that we have quite alot
of code using qemu_log_trylock + qemu_log, instead of qemu_log_trylock
+ fprintf.

I didn't feel it appropriate to use 'must' unless we explicitly make
qemu_log() fail when used inside the scope of a qemu_log_trylock().

So "Should normally" is the best fit

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 :|

On Tue, Jan 13, 2026 at 10:49:01AM +0000, Daniel P. Berrangé via Devel wrote:
> On Tue, Jan 13, 2026 at 10:59:49AM +0100, Markus Armbruster wrote:
> > Daniel P. Berrangé <berrange@redhat.com> writes:
> > 
> > > There is a gotcha with qemu_log() usage in a threaded process.
> > > If fragments of a log message are output via qemu_log() it is
> > > possible for messages from two threads to get mixed up. To
> > > prevent this qemu_log_trylock() should be used, along with
> > > fprintf(f) calls.
> > >
> > > This is a subtle problem that needs to be explained in the
> > > API docs to ensure correct usage.
> > >
> > > Reported-by: Markus Armbruster <armbru@redhat.com>
> > > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > > ---
> > >  include/qemu/log-for-trace.h | 17 ++++++++++++++++-
> > >  include/qemu/log.h           | 31 +++++++++++++++++++++++++++++++
> > >  rust/util/src/log.rs         |  6 ++++++
> > >  3 files changed, 53 insertions(+), 1 deletion(-)
> > >
> > > diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
> > > index f3a8791f1d..6861a1a4b7 100644
> > > --- a/include/qemu/log-for-trace.h
> > > +++ b/include/qemu/log-for-trace.h
> > > @@ -29,7 +29,22 @@ static inline bool qemu_loglevel_mask(int mask)
> > >      return (qemu_loglevel & mask) != 0;
> > >  }
> > >  
> > > -/* main logging function */
> > > +/**
> > > + * qemu_log: report a log message
> > > + * @fmt: the format string for the message
> > > + * @...: the format string arguments
> > > + *
> > > + * This will emit a log message to the current output stream.
> > > + *
> > > + * The @fmt string should normally represent a complete line
> > > + * of text, and thus end with a newline character.
> > 
> > Note for later: "should normally".
> > 
> > > + *
> > > + * While it is possible to incrementally output fragments of
> > > + * a complete line using qemu_log, this is inefficient and
> > > + * races with other threads. For outputting fragments it is
> > > + * strongly preferred to use the qemu_log_trylock() method
> > > + * combined with fprintf().
> > > + */
> > >  void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);
> > >  
> > >  #endif
> > > diff --git a/include/qemu/log.h b/include/qemu/log.h
> > > index 7effba4da4..e9d3c6806b 100644
> > > --- a/include/qemu/log.h
> > > +++ b/include/qemu/log.h
> > > @@ -41,7 +41,38 @@ bool qemu_log_separate(void);
> > >  
> > >  /* Lock/unlock output. */
> > >  
> > > +/**
> > > + * Acquires a lock on the current log output stream.
> > > + * The returned FILE object should be used with the
> > > + * fprintf() function to output the log message, and
> > > + * then qemu_log_unlock() called to release the lock.
> > > + *
> > > + * The primary use case is to be able to incrementally
> > > + * output fragments of a complete log message in an
> > > + * efficient and race free manner.
> > > + *
> > > + * The simpler qemu_log() method must only be used
> > > + * to output complete log messages.
> > 
> > "must".
> > 
> > > + *
> > > + * A typical usage pattern would be
> > > + *
> > > + *    FILE *f = qemu_log_trylock()
> > > + *
> > > + *    fprintf(f, "Something ");
> > > + *    fprintf(f, "Something ");
> > > + *    fprintf(f, "Something ");
> > > + *    fprintf(f, "The end\n");
> > > + *
> > > + *    qemu_log_unlock(f);
> > > + *
> > > + * Returns: the current FILE if available, NULL on error
> > > + */
> > >  FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT;
> > > +
> > > +/**
> > > + * Releases the lock on the log output, previously
> > > + * acquired by qemu_log_trylock().
> > > + */
> > >  void qemu_log_unlock(FILE *fd);
> > >  
> > >  /* Logging functions: */
> > > diff --git a/rust/util/src/log.rs b/rust/util/src/log.rs
> > > index 0a4bc4249a..6a3a30d8d8 100644
> > > --- a/rust/util/src/log.rs
> > > +++ b/rust/util/src/log.rs
> > > @@ -134,6 +134,12 @@ fn drop(&mut self) {
> > >  ///     "Address 0x{:x} out of range",
> > >  ///     error_address,
> > >  /// );
> > > +///
> > > +/// The `log_mask_ln` macro should only be used for emitting complete
> > 
> > "should only".
> > 
> > > +/// log messages. Where it is required to incrementally output string
> > > +/// fragments to construct a complete message, `LogGuard::new()` should
> > > +/// be directly used in combination with `writeln()` to avoid output
> > > +/// races with other QEMU threads.
> > >  /// ```
> > >  #[macro_export]
> > >  macro_rules! log_mask_ln {
> > 
> > "Should normally" suggests there are exceptions.
> > 
> > "Should only" does not.
> > 
> > "Must" is a bit stronger still.
> > 
> > Which of the three do we want?
> 
> The "Should" usage was reflecting the reality that we have quite alot
> of code using qemu_log_trylock + qemu_log, instead of qemu_log_trylock
> + fprintf.
> 
> I didn't feel it appropriate to use 'must' unless we explicitly make
> qemu_log() fail when used inside the scope of a qemu_log_trylock().
> 
> So "Should normally" is the best fit

Actually specifically in the log.rs case, we have a greater constraint.
The rust code for log_mask_ln will unconditionally add a newline to
all messages. So this Rust method *must* only be usd for complete
messages, regardless of what policy we have on the C qemu_log() call.

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 :|

Daniel P. Berrangé <berrange@redhat.com> writes:

> On Tue, Jan 13, 2026 at 10:49:01AM +0000, Daniel P. Berrangé via Devel wrote:
>> On Tue, Jan 13, 2026 at 10:59:49AM +0100, Markus Armbruster wrote:
>> > Daniel P. Berrangé <berrange@redhat.com> writes:
>> > 
>> > > There is a gotcha with qemu_log() usage in a threaded process.
>> > > If fragments of a log message are output via qemu_log() it is
>> > > possible for messages from two threads to get mixed up. To
>> > > prevent this qemu_log_trylock() should be used, along with
>> > > fprintf(f) calls.
>> > >
>> > > This is a subtle problem that needs to be explained in the
>> > > API docs to ensure correct usage.
>> > >
>> > > Reported-by: Markus Armbruster <armbru@redhat.com>
>> > > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>

[...]

>> > "Should normally" suggests there are exceptions.
>> > 
>> > "Should only" does not.
>> > 
>> > "Must" is a bit stronger still.
>> > 
>> > Which of the three do we want?
>> 
>> The "Should" usage was reflecting the reality that we have quite alot
>> of code using qemu_log_trylock + qemu_log, instead of qemu_log_trylock
>> + fprintf.

Yes.

>> I didn't feel it appropriate to use 'must' unless we explicitly make
>> qemu_log() fail when used inside the scope of a qemu_log_trylock().

Fair.

>> So "Should normally" is the best fit
>
> Actually specifically in the log.rs case, we have a greater constraint.
> The rust code for log_mask_ln will unconditionally add a newline to
> all messages. So this Rust method *must* only be usd for complete
> messages, regardless of what policy we have on the C qemu_log() call.

Got it.

Suggest to consistently use "should normally" in the contracts where it
is the best fit.  Use "must" for the Rust method, and maybe mention it
in the commit message (you decide).