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>
---
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, ...)
va_start(ap, fmt);
vfprintf(f, fmt, ap);
va_end(ap);
+ incomplete = fmt[strlen(fmt) - 1] != '\n';
qemu_log_unlock(f);
}
}
--
2.50.1
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.
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
This is a slightly wierd API design, but that seems to be
the intended way to serailize and in that context, my
patch/hack here will be sufficiently good.
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 :|
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.
> This is a slightly wierd API design,
More seriously: entirely undocumented. The only hint is the presence of
qemu_log_trylock() and qemu_log_unlock().
> but that seems to be
> the intended way to serailize and in that context, my
> patch/hack here will be sufficiently good.
Right, the flockfile() locks out the other thread.
I feel this is more complex than it ought to be. It also lacks comments
explaining the locking.
On a green field, I'd make the logging function append a newline. When
the line to be logged is to be built up with multiple printf-like calls,
use g_string_printf(). If you're worried about reallocations, use
something like g_string_sized_new(512). Log lines longer than that
would be masochism anyway. If even that single allocation bothers you,
build your logging around fixed thread-local buffers, avoiding stdio.
No objection to your patch. It digs us deeper into this hole, but we
got worse holes to worry about.
Pondering the interleave between logging and error reporting led me to an interleave between error reporting and itself. vreport() prints a single line to stderr in several parts: * Timestamp (if enabled) * Guest name (if enabled) * Program name * Location (if there is one) * Message type * Message text * Newline Stdio guarantees that each part comes out as a whole even when other threads print to the same FILE at the same time. But another thread's print output can still squeeze in between parts. Unlikely, but possible. To avoid it, we'd need to guard vreport()'s printing with flockfile() ... funlockfile(). Thoughts?
On Wed, Sep 24, 2025 at 02:34:30PM +0200, Markus Armbruster wrote: > Pondering the interleave between logging and error reporting led me to > an interleave between error reporting and itself. > > vreport() prints a single line to stderr in several parts: > > * Timestamp (if enabled) > > * Guest name (if enabled) > > * Program name > > * Location (if there is one) > > * Message type > > * Message text > > * Newline > > Stdio guarantees that each part comes out as a whole even when other > threads print to the same FILE at the same time. But another thread's > print output can still squeeze in between parts. Unlikely, but > possible. To avoid it, we'd need to guard vreport()'s printing with > flockfile() ... funlockfile(). > > Thoughts? You are totally correct. The qemu_log code will do the right thing with flockfile /funlockfile, but we're missing that serialization in the error report code. It doesn't matter quite as much as logging, since much of time when error_report is used, it is in a scenario that is likely to either be serialized, or be about to call exit/ abort. None the less I'm sure we can come up with real world scenarios where error report will be concurrent in QEMU that can interleave, so we should add the flockfile usage. 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 :|
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> snip > > 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. > > > This is a slightly wierd API design, > > More seriously: entirely undocumented. The only hint is the presence of > qemu_log_trylock() and qemu_log_unlock(). I'm including a new patch that starts some API docs for the log APIs. 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 :|
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 :|
On 10/9/25 20:03, Daniel P. Berrangé wrote: > 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> > --- > util/log.c | 9 ++++++++- > 1 file changed, 8 insertions(+), 1 deletion(-) Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
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.
>
Have you considered
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>
> ---
> 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;
Thread-local only because we have @log_per_thread, isn't it?
> +
> 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, ...)
> va_start(ap, fmt);
> vfprintf(f, fmt, ap);
> va_end(ap);
> + incomplete = fmt[strlen(fmt) - 1] != '\n';
> qemu_log_unlock(f);
> }
> }
On Wed, Sep 17, 2025 at 04:11:44PM +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.
> >
>
> Have you considered
>
> 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>
> > ---
> > 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;
>
> Thread-local only because we have @log_per_thread, isn't it?
Pretty much. If you're not using log_per_thread, then code which
incrementally emits a single line using multiple qemu_log calls
is doomed in a concurrency sitation, but this __thread at least
doesn't make the situation worse than it already is.
>
> > +
> > 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, ...)
> > va_start(ap, fmt);
> > vfprintf(f, fmt, ap);
> > va_end(ap);
> > + incomplete = fmt[strlen(fmt) - 1] != '\n';
> > qemu_log_unlock(f);
> > }
> > }
>
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 :|
On 9/10/25 18:03, Daniel P. Berrangé wrote:
> 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>
> ---
> util/log.c | 9 ++++++++-
> 1 file changed, 8 insertions(+), 1 deletion(-)
Reviewed-by: Richard Henderson <richard.henderson@linaro.org>
r~>
> 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, ...)
> va_start(ap, fmt);
> vfprintf(f, fmt, ap);
> va_end(ap);
> + incomplete = fmt[strlen(fmt) - 1] != '\n';
> qemu_log_unlock(f);
> }
> }
* Daniel P. Berrangé (berrange@redhat.com) wrote:
> 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>
Reviewed-by: Dr. David Alan Gilbert <dave@treblig.org>
> ---
> 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, ...)
> va_start(ap, fmt);
> vfprintf(f, fmt, ap);
> va_end(ap);
> + incomplete = fmt[strlen(fmt) - 1] != '\n';
> qemu_log_unlock(f);
> }
> }
> --
> 2.50.1
>
--
-----Open up your eyes, open up your mind, open up your code -------
/ Dr. David Alan Gilbert | Running GNU/Linux | Happy \
\ dave @ treblig.org | | In Hex /
\ _________________________|_____ http://www.treblig.org |_______/
© 2016 - 2025 Red Hat, Inc.