Re: [PATCH v3 08/20] log: avoid repeated prefix on incremental qemu_log calls

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

On Wed, Sep 24, 2025 at 09:06:55AM +0200, Markus Armbruster wrote:
> Daniel P. Berrangé <berrange@redhat.com> writes:
> 
> > On Tue, Sep 23, 2025 at 04:28:42PM +0200, Markus Armbruster wrote:
> >> Daniel P. Berrangé <berrange@redhat.com> writes:
> >> 
> >> > Some code makes multiple qemu_log calls to incrementally emit
> >> > a single message. Currently timestamps get prepended to all
> >> > qemu_log calls, even those continuing a previous incomplete
> >> > message.
> >> >
> >> > This changes the qemu_log so it skips adding a new line prefix,
> >> > if the previous qemu_log call did NOT end with a newline.
> >> >
> >> > Reported-by: Richard Henderson <richard.henderson@linaro.org>
> >> > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> >> 
> >> This patch has kept nagging me in the back of my brain.  So I'm back for
> >> a second look.
> >> 
> >> > ---
> >> >  util/log.c | 9 ++++++++-
> >> >  1 file changed, 8 insertions(+), 1 deletion(-)
> >> >
> >> > diff --git a/util/log.c b/util/log.c
> >> > index abdcb6b311..2642a55c59 100644
> >> > --- a/util/log.c
> >> > +++ b/util/log.c
> >> > @@ -143,6 +143,12 @@ void qemu_log_unlock(FILE *logfile)
> >> >      }
> >> >  }
> >> >  
> >> > +/*
> >> > + * 'true' if the previous log message lacked a trailing '\n',
> >> > + * and thus the subsequent call must skip any prefix
> >> > + */
> >> > +static __thread bool incomplete;
> >> > +
> >> >  void qemu_log(const char *fmt, ...)
> >> >  {
> >> >      FILE *f;
> >> > @@ -154,7 +160,7 @@ void qemu_log(const char *fmt, ...)
> >> >       * was emitted if we are delayed acquiring the
> >> >       * mutex
> >> >       */
> >> > -    if (message_with_timestamp) {
> >> > +    if (message_with_timestamp && !incomplete) {
> >> >          g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
> >> >          timestr = g_date_time_format_iso8601(dt);
> >> >      }
> >> > @@ -170,6 +176,7 @@ void qemu_log(const char *fmt, ...)
> >>        f = qemu_log_trylock();
> >>        if (f) {
> >>            va_list ap;
> >> 
> >>            if (timestr) {
> >>                fprintf(f, "%s ", timestr);
> >>            }
> >> 
> >> >          va_start(ap, fmt);
> >> >          vfprintf(f, fmt, ap);
> >> >          va_end(ap);
> >> > +        incomplete = fmt[strlen(fmt) - 1] != '\n';
> >> >          qemu_log_unlock(f);
> >> >      }
> >> >  }
> >> 
> >> Two cases:
> >> 
> >> (A) Single log
> >> 
> >>     qemu_log_trylock() returns @global_file, and uses RCU to ensure it
> >>     remains valid until qemu_log_unlock().  I think.
> >> 
> >> (B) Log split per thread (-d tid)
> >> 
> >>     qemu_log_trylock() returns thread-local @thread_file.
> >> 
> >> In addition, qemu_log_trylock() locks the FILE it returns with
> >> flockfile(), so no other thread can write to it until qemu_log_unlock()
> >> unlocks it with funlockfile().  This ensures the entire output of in
> >> between stays together.
> >> 
> >> Let's see how this plays with @incomplete.
> >> 
> >> (B) Log split per thread (-d tid)
> >> 
> >>     @incomplete is thread-local.  It records wether the last qemu_log()
> >>     in this thread was an incomplete line.  If it was, the next
> >>     qemu_log() continues the line.  Unless something else wrote to
> >>     @thread_file in between, but that's not supposed to happen.  Good.
> >> 
> >> (A) Single log
> >> 
> >>     All thread log to the same FILE.  Consider:
> >> 
> >>     1. Thread 1 starts.  Its @incomplete is initialized to false.
> >> 
> >>     2. Thread 2 starts.  Its @incomplete is initialized to false.
> >> 
> >>     3. Thread 1 logs "abra".  Its @incomplete is set to true.
> >> 
> >>     4. Thread 2 logs "interrupt\n".  Its @incomplete remains false.
> >> 
> >>     5. Thread 2 logs "cadbra\n".  Its @incomplete goes back to false.
> >> 
> >>     Resulting log file contents:
> >> 
> >>         PREFIX "abra" PREFIX "interrupt\n"
> >>         "cadabra\n"
> >> 
> >>     Not good.
> >> 
> >> We could complicate this code further to mitigate.  For instance, we
> >> could use a thread-local @incomplete for (B), and a global one for (A).
> >> This ensures log lines start with PREFIX as they should, but does
> >> nothing to avoid mixing up line parts from different threads.  My
> >> example would then produce
> >> 
> >>         PREFIX "abrainterrupt\n"
> >>         PREFIX "cababra\n"
> >> 
> >> My take: "Doctor, it hurts when I do that!"  "Don't do that then."
> >> Logging incomplete lines with qemu_log() can hurt.  Don't do that then.
> >
> > I just took a look at linux-user/syscall.c as that is one place that
> > heavily uses qemu_log() for incomplete lines.
> >
> > What I didn't realize was that the expectation is to call
> > qemu_log_trylock() (which returns the "FILE *" target) and
> > then you can ignore the "FILE *" and just call qemu_log()
> > repeatedly, and finally call qemu_log_unlock(FILE *) when
> > done.
> >
> > https://gitlab.com/qemu-project/qemu/-/blob/master/linux-user/strace.c?ref_type=heads#L4396
> 
> I can see the qemu_log_trylock() / qemu_log_unlock() bracket.  But the
> code within doesn't work the way you describe: it uses fprintf(f, ...).
> If it did ignore @f and call qemu_log(), qemu_log() would
> qemu_log_trylock() again, taking the RCU read lock and the flockfile()
> lock on @f recursively.  Should work.


Only the fallback path (the 'else' branch) uses fprintf.

The main path is doing

 scnames[i].call(cpu_env, &scnames[i], arg1, arg2, arg3,
                                arg4, arg5, arg6);

which calls out to the other countless 'print_XXXX' methods,
one per syscall, which all use qemu_log().


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