There is a gotcha with qemu_log() usage in a threaded process. If fragments of a log message are output via qemu_log() it is possible for messages from two threads to get mixed up. To prevent this qemu_log_trylock() should be used, along with fprintf(f) calls. This is a subtle problem that needs to be explained in the API docs to ensure correct usage. In the Rust code, the log_mask_ln method which is conceptually equivalent to the C qemu_log() call will unconditionally append a newline so must only ever be used for complete log messages. Reported-by: Markus Armbruster <armbru@redhat.com> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- include/qemu/log-for-trace.h | 17 ++++++++++++++++- include/qemu/log.h | 32 ++++++++++++++++++++++++++++++++ rust/util/src/log.rs | 6 ++++++ 3 files changed, 54 insertions(+), 1 deletion(-) diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h index f3a8791f1d..6861a1a4b7 100644 --- a/include/qemu/log-for-trace.h +++ b/include/qemu/log-for-trace.h @@ -29,7 +29,22 @@ 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, and thus end with a newline character. + * + * While it is possible to incrementally output fragments of + * a complete line using qemu_log, this is inefficient and + * races with other threads. For outputting fragments it is + * strongly preferred to use the qemu_log_trylock() method + * combined with fprintf(). + */ 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 7effba4da4..b49a1a5fe3 100644 --- a/include/qemu/log.h +++ b/include/qemu/log.h @@ -41,7 +41,39 @@ bool qemu_log_separate(void); /* Lock/unlock output. */ +/** + * Acquires a lock on the current log output stream. + * The returned FILE object should be used with the + * fprintf() function to output the log message, and + * then qemu_log_unlock() called to release the lock. + * + * The primary use case is to be able to incrementally + * output fragments of a complete log message in an + * efficient and race free manner. + * + * The simpler qemu_log() method should normally only + * be used to output complete log messages, and not + * within scope of a qemu_log_trylock() call. + * + * A typical usage pattern would be + * + * FILE *f = qemu_log_trylock() + * + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "Something "); + * fprintf(f, "The end\n"); + * + * qemu_log_unlock(f); + * + * 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 0a4bc4249a..1116570790 100644 --- a/rust/util/src/log.rs +++ b/rust/util/src/log.rs @@ -135,6 +135,12 @@ fn drop(&mut self) { /// error_address, /// ); /// ``` +/// +/// The `log_mask_ln` macro must only be used for emitting complete +/// log messages. Where it is required to incrementally output string +/// fragments to construct a complete message, `LogGuard::new()` must +/// be directly used in combination with `writeln()` to avoid output +/// races with other QEMU threads. #[macro_export] macro_rules! log_mask_ln { ($mask:expr, $fmt:tt $($args:tt)*) => {{ -- 2.53.0