Re: [PATCH v4 09/23] util: introduce some API docs for logging APIs

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

On Thu, Sep 25, 2025 at 05:02:37PM -0700, Richard Henderson wrote:
> On 9/25/25 02:44, Daniel P. Berrangé wrote:
> > This addresses two key gotchas with the logging APIs:
> > 
> >   * Safely outputting a single line of text using
> >     multiple qemu_log() calls requires use of the
> >     qemu_log_trylock/unlock functions to avoid
> >     interleaving between threads
> > 
> >   * Directly outputting to the FILE object returned
> >     by qemu_log_trylock() must be discouraged because
> >     it prevents the inclusion of configured log message
> >     prefixes.
> 
> I disagree with this point.
> 
> > 
> > Reported-by: Markus Armbruster <armbru@redhat.com>
> > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > ---
> >   include/qemu/log-for-trace.h | 35 ++++++++++++++++++++++++++++++++++-
> >   include/qemu/log.h           | 26 ++++++++++++++++++++++++++
> >   rust/util/src/log.rs         |  7 +++++++
> >   3 files changed, 67 insertions(+), 1 deletion(-)
> > 
> > diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
> > index d47c9cd446..4e05b2e26f 100644
> > --- a/include/qemu/log-for-trace.h
> > +++ b/include/qemu/log-for-trace.h
> > @@ -29,7 +29,40 @@ 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, ending with a newline character.
> > + *
> > + * If intending to call this function multiple times to
> > + * incrementally construct a line of text, locking must
> > + * be used to ensure that output from different threads
> > + * is not interleaved.
> > + *
> > + * This is achieved by calling qemu_log_trylock() before
> > + * starting the log line; calling qemu_log() multiple
> > + * times with the last call having a newline at the end
> > + * of @fmt; finishing with a call to qemu_log_unlock().
> > + *
> > + * The FILE object returned by qemu_log_trylock() does
> > + * not need to be used for outputting text directly,
> > + * it is merely used to associate the lock.
> > + *
> > + *    FILE *f = qemu_log_trylock()
> > + *
> > + *    qemu_log("Something");
> > + *    qemu_log("Something");
> > + *    qemu_log("Something");
> > + *    qemu_log("The end\n");
> > + *
> > + *    qemu_log_unlock(f);
> > + *
> 
> And I really don't like documenting this as the "right way".
> 
> I believe that qemu_log *should* be used only for single-line output, all in
> one piece. Larger blocks *should* always use qemu_log_trylock and fprintf.
> The compiler has optimizations transforming fprintf to fputs and fputc as
> appropriate.

Ok, bearing in mind your suggestion below, I'll flip this around.
The above  doc would instruct people to NOT use qemu_log for
incomplete lines (though it would still be accepted), and then
qemu_log_trylock() docs can recommend the best practice for
incremental line output.

> If we can manage to transform all existing usage of multiple qemu_log, then
> we can remove the '\n' detection added in patch 8.

The challenge with that is that we have no easy way to identify all
such usage other than incredibly tedious auditing of every single
file with more than one qemu_log call. And then we also can't easil
prevent it being re-introduced as a problem.

> 
> As far as adding the new prefixes... perhaps we should have something like
> 
> FILE *qemu_log_trylock_and_context(bool suppress_context)
> {
>     FILE *f = qemu_log_trylock();
>     if (f && !suppress_context) {
>         qmessage_context_print(f);
>     }
>     return f;
> }
> 
> where qemu_log would do
> 
>     f = qemu_log_trylock_and_context(incomplete);

That's a nice idea, as it brings the prefixes into the codepaths which
avoid qemu_log(). I'll try that out.

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