Re: [PATCH v5 09/24] util: introduce some API docs for logging APIs

["Daniel P. Berrangé" <berrange@redhat.com>]

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