Daniel P. Berrangé <[email protected]> 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 <[email protected]>
> Signed-off-by: Daniel P. Berrangé <[email protected]>
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.
