Re: [PATCH v5 10/24] util: avoid repeated prefix on incremental qemu_log calls

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

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