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

Daniel P. Berrangé posted 23 patches 3 days, 5 hours ago
Maintainers: Gerd Hoffmann <kraxel@redhat.com>, Christian Schoenebeck <qemu_oss@crudebyte.com>, Markus Armbruster <armbru@redhat.com>, Paolo Bonzini <pbonzini@redhat.com>, "Marc-André Lureau" <marcandre.lureau@redhat.com>, "Daniel P. Berrangé" <berrange@redhat.com>, "Philippe Mathieu-Daudé" <philmd@linaro.org>, "Dr. David Alan Gilbert" <dave@treblig.org>, Manos Pitsidianakis <manos.pitsidianakis@linaro.org>, Kevin Wolf <kwolf@redhat.com>, Hanna Reitz <hreitz@redhat.com>, Stefan Weil <sw@weilnetz.de>
[PATCH v4 09/23] util: introduce some API docs for logging APIs
Posted by Daniel P. Berrangé via Devel 3 days, 5 hours ago
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.

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);
+ *
+ */
 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 aae72985f0..867fe327e4 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -41,7 +41,33 @@ bool qemu_log_separate(void);
 
 /* Lock/unlock output. */
 
+/**
+ * Acquires a lock on the current log output stream.
+ * The returned FILE object must be passed to
+ * qemu_log_unlock() to later release the lock.
+ *
+ * This should be used to protect a sequence of calls
+ * to qemu_log(), if they are being used to incrementally
+ * output a single line of text. For qemu_log() calls which
+ * output a complete line of text it is not required to
+ * take explicit locks.
+ *
+ * The returned FILE object may be used to directly
+ * output log messages, however, doing so will prevent
+ * the inclusion of configured log message prefixes.
+ * It is thus recommended that this be used sparingly,
+ * only in cases where it is required to dump large
+ * data volumes. Use of qemu_log() is preferred for
+ * most output tasks.
+ *
+ * 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 af9a3e9123..eaf493f0df 100644
--- a/rust/util/src/log.rs
+++ b/rust/util/src/log.rs
@@ -55,6 +55,13 @@ impl LogGuard {
     ///     writeln!(log, "test");
     /// }
     /// ```
+    ///
+    /// Note that directly writing to the log output will prevent the
+    /// inclusion of configured log prefixes. It is thus recommended
+    /// that this be used sparingly, only in cases where it is required
+    /// to dump large data volumes. Use of [`log_mask_ln!()`](crate::log_mask_ln)
+    /// macro() is preferred for most output tasks.
+
     pub fn new() -> Option<Self> {
         let f = unsafe { bindings::qemu_log_trylock() }.cast();
         NonNull::new(f).map(Self)
-- 
2.50.1

Re: [PATCH v4 09/23] util: introduce some API docs for logging APIs
Posted by Richard Henderson 2 days, 14 hours ago
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.

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

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


r~

Re: [PATCH v4 09/23] util: introduce some API docs for logging APIs
Posted by Daniel P. Berrangé 2 days ago
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 :|


Re: [PATCH v4 09/23] util: introduce some API docs for logging APIs
Posted by Eric Blake via Devel 2 days, 17 hours ago
On Thu, Sep 25, 2025 at 10:44:27AM +0100, 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.
> 
> Reported-by: Markus Armbruster <armbru@redhat.com>
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---

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

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

Should this example include spaces, as in qemu_log("Something ");, so
that copy-and-paste coding is less likely to
ResultInCompressedSentences across the log calls?

Adjusting a comment is trivial, so:

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.
Virtualization:  qemu.org | libguestfs.org