* [PATCH 0/4] Make the qemu_logfile handle thread safe.
@ 2019-11-07 14:26 Robert Foley
2019-11-07 14:26 ` [PATCH 1/4] Add a mutex to guarantee single writer to qemu_logfile handle Robert Foley
` (5 more replies)
0 siblings, 6 replies; 19+ messages in thread
From: Robert Foley @ 2019-11-07 14:26 UTC (permalink / raw)
To: qemu-devel; +Cc: peter.puhov, alex.bennee, robert.foley
This patch adds thread safety to the qemu_logfile handle. This now
allows changing the logfile while logging is active, and also solves
the issue of a seg fault while changing the logfile.
This patch adds use of RCU for handling the swap out of the
old qemu_logfile file descriptor.
Robert Foley (4):
Add a mutex to guarantee single writer to qemu_logfile handle.
Add use of RCU for qemu_logfile.
qemu_log_lock/unlock now preserves the qemu_logfile handle.
Added tests for close and change of logfile.
accel/tcg/cpu-exec.c | 4 +-
accel/tcg/translate-all.c | 4 +-
accel/tcg/translator.c | 4 +-
exec.c | 4 +-
hw/net/can/can_sja1000.c | 4 +-
include/exec/log.h | 33 ++++++++++--
include/qemu/log.h | 51 +++++++++++++++---
net/can/can_socketcan.c | 5 +-
target/cris/translate.c | 4 +-
target/i386/translate.c | 5 +-
target/lm32/translate.c | 4 +-
target/microblaze/translate.c | 4 +-
target/nios2/translate.c | 4 +-
target/tilegx/translate.c | 7 +--
target/unicore32/translate.c | 4 +-
tcg/tcg.c | 28 ++++++----
tests/test-logging.c | 74 ++++++++++++++++++++++++++
util/log.c | 99 ++++++++++++++++++++++++++++-------
18 files changed, 273 insertions(+), 69 deletions(-)
--
2.17.1
^ permalink raw reply [flat|nested] 19+ messages in thread
* [PATCH 1/4] Add a mutex to guarantee single writer to qemu_logfile handle.
2019-11-07 14:26 [PATCH 0/4] Make the qemu_logfile handle thread safe Robert Foley
@ 2019-11-07 14:26 ` Robert Foley
2019-11-07 16:53 ` Alex Bennée
2019-11-07 14:26 ` [PATCH 2/4] Add use of RCU for qemu_logfile Robert Foley
` (4 subsequent siblings)
5 siblings, 1 reply; 19+ messages in thread
From: Robert Foley @ 2019-11-07 14:26 UTC (permalink / raw)
To: qemu-devel; +Cc: peter.puhov, alex.bennee, robert.foley
This is being added in preparation for using RCU with the logfile handle.
Also added qemu_logfile_init() for initializing the logfile mutex.
Signed-off-by: Robert Foley <robert.foley@linaro.org>
---
util/log.c | 23 +++++++++++++++++++++++
1 file changed, 23 insertions(+)
diff --git a/util/log.c b/util/log.c
index 1ca13059ee..dff2f98c8c 100644
--- a/util/log.c
+++ b/util/log.c
@@ -24,8 +24,11 @@
#include "qapi/error.h"
#include "qemu/cutils.h"
#include "trace/control.h"
+#include "qemu/thread.h"
static char *logfilename;
+static bool qemu_logfile_initialized;
+static QemuMutex qemu_logfile_mutex;
FILE *qemu_logfile;
int qemu_loglevel;
static int log_append = 0;
@@ -49,6 +52,14 @@ int qemu_log(const char *fmt, ...)
return ret;
}
+static void qemu_logfile_init(void)
+{
+ if (!qemu_logfile_initialized) {
+ qemu_mutex_init(&qemu_logfile_mutex);
+ qemu_logfile_initialized = true;
+ }
+}
+
static bool log_uses_own_buffers;
/* enable or disable low levels log */
@@ -58,6 +69,12 @@ void qemu_set_log(int log_flags)
#ifdef CONFIG_TRACE_LOG
qemu_loglevel |= LOG_TRACE;
#endif
+
+ /* Is there a better place to call this to init the logfile subsystem? */
+ if (!qemu_logfile_initialized) {
+ qemu_logfile_init();
+ }
+ qemu_mutex_lock(&qemu_logfile_mutex);
if (!qemu_logfile &&
(is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
if (logfilename) {
@@ -93,6 +110,7 @@ void qemu_set_log(int log_flags)
log_append = 1;
}
}
+ qemu_mutex_unlock(&qemu_logfile_mutex);
if (qemu_logfile &&
(is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
qemu_log_close();
@@ -114,6 +132,11 @@ void qemu_set_log_filename(const char *filename, Error **errp)
char *pidstr;
g_free(logfilename);
+ /* Is there a better place to call this to init the logfile subsystem? */
+ if (!qemu_logfile_initialized) {
+ qemu_logfile_init();
+ }
+
pidstr = strstr(filename, "%");
if (pidstr) {
/* We only accept one %d, no other format strings */
--
2.17.1
^ permalink raw reply related [flat|nested] 19+ messages in thread
* [PATCH 2/4] Add use of RCU for qemu_logfile.
2019-11-07 14:26 [PATCH 0/4] Make the qemu_logfile handle thread safe Robert Foley
2019-11-07 14:26 ` [PATCH 1/4] Add a mutex to guarantee single writer to qemu_logfile handle Robert Foley
@ 2019-11-07 14:26 ` Robert Foley
2019-11-07 16:23 ` Alex Bennée
2019-11-07 14:26 ` [PATCH 3/4] qemu_log_lock/unlock now preserves the qemu_logfile handle Robert Foley
` (3 subsequent siblings)
5 siblings, 1 reply; 19+ messages in thread
From: Robert Foley @ 2019-11-07 14:26 UTC (permalink / raw)
To: qemu-devel; +Cc: peter.puhov, alex.bennee, robert.foley
This now allows changing the logfile while logging is active,
and also solves the issue of a seg fault while changing the logfile.
Any read access to the qemu_logfile handle will use
the rcu_read_lock()/unlock() around the use of the handle.
To fetch the handle we will use atomic_rcu_read().
We also in many cases do a check for validity of the
logfile handle before using it to deal with the case where the
file is closed and set to NULL.
The cases where we write to the qemu_logfile will use atomic_rcu_set().
Writers will also use call_rcu() with a newly added qemu_logfile_free
function for freeing/closing when readers have finished.
Signed-off-by: Robert Foley <robert.foley@linaro.org>
---
include/qemu/log.h | 47 ++++++++++++++++++++++++----
util/log.c | 78 ++++++++++++++++++++++++++++++++++------------
include/exec/log.h | 33 +++++++++++++++++---
tcg/tcg.c | 12 +++++--
4 files changed, 138 insertions(+), 32 deletions(-)
diff --git a/include/qemu/log.h b/include/qemu/log.h
index a91105b2ad..975de18e23 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -3,9 +3,17 @@
/* A small part of this API is split into its own header */
#include "qemu/log-for-trace.h"
+#include "qemu/rcu.h"
+
+struct QemuLogFile {
+ struct rcu_head rcu;
+ FILE *fd;
+};
+typedef struct QemuLogFile QemuLogFile;
/* Private global variable, don't use */
-extern FILE *qemu_logfile;
+extern QemuLogFile *qemu_logfile;
+
/*
* The new API:
@@ -25,7 +33,17 @@ static inline bool qemu_log_enabled(void)
*/
static inline bool qemu_log_separate(void)
{
- return qemu_logfile != NULL && qemu_logfile != stderr;
+ QemuLogFile *logfile;
+
+ if (qemu_log_enabled()) {
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile && logfile->fd != stderr) {
+ return true;
+ }
+ rcu_read_unlock();
+ }
+ return false;
}
#define CPU_LOG_TB_OUT_ASM (1 << 0)
@@ -55,12 +73,23 @@ static inline bool qemu_log_separate(void)
static inline void qemu_log_lock(void)
{
- qemu_flockfile(qemu_logfile);
+ QemuLogFile *logfile;
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ qemu_flockfile(logfile->fd);
+ }
+ rcu_read_unlock();
}
static inline void qemu_log_unlock(void)
{
- qemu_funlockfile(qemu_logfile);
+ QemuLogFile *logfile;
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ qemu_funlockfile(logfile->fd);
+ }
+ rcu_read_unlock();
}
/* Logging functions: */
@@ -70,9 +99,14 @@ static inline void qemu_log_unlock(void)
static inline void GCC_FMT_ATTR(1, 0)
qemu_log_vprintf(const char *fmt, va_list va)
{
- if (qemu_logfile) {
- vfprintf(qemu_logfile, fmt, va);
+ QemuLogFile *logfile;
+
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ vfprintf(logfile->fd, fmt, va);
}
+ rcu_read_unlock();
}
/* log only if a bit is set on the current loglevel mask:
@@ -129,5 +163,6 @@ void qemu_print_log_usage(FILE *f);
void qemu_log_flush(void);
/* Close the log file */
void qemu_log_close(void);
+void qemu_logfile_free(QemuLogFile *logfile);
#endif
diff --git a/util/log.c b/util/log.c
index dff2f98c8c..d409532b8f 100644
--- a/util/log.c
+++ b/util/log.c
@@ -29,7 +29,7 @@
static char *logfilename;
static bool qemu_logfile_initialized;
static QemuMutex qemu_logfile_mutex;
-FILE *qemu_logfile;
+QemuLogFile *qemu_logfile;
int qemu_loglevel;
static int log_append = 0;
static GArray *debug_regions;
@@ -38,10 +38,14 @@ static GArray *debug_regions;
int qemu_log(const char *fmt, ...)
{
int ret = 0;
- if (qemu_logfile) {
+ QemuLogFile *logfile;
+
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
va_list ap;
va_start(ap, fmt);
- ret = vfprintf(qemu_logfile, fmt, ap);
+ ret = vfprintf(logfile->fd, fmt, ap);
va_end(ap);
/* Don't pass back error results. */
@@ -49,6 +53,7 @@ int qemu_log(const char *fmt, ...)
ret = 0;
}
}
+ rcu_read_unlock();
return ret;
}
@@ -65,6 +70,8 @@ static bool log_uses_own_buffers;
/* enable or disable low levels log */
void qemu_set_log(int log_flags)
{
+ QemuLogFile *logfile;
+
qemu_loglevel = log_flags;
#ifdef CONFIG_TRACE_LOG
qemu_loglevel |= LOG_TRACE;
@@ -77,43 +84,51 @@ void qemu_set_log(int log_flags)
qemu_mutex_lock(&qemu_logfile_mutex);
if (!qemu_logfile &&
(is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
+ logfile = g_new0(QemuLogFile, 1);
if (logfilename) {
- qemu_logfile = fopen(logfilename, log_append ? "a" : "w");
- if (!qemu_logfile) {
+ logfile->fd = fopen(logfilename, log_append ? "a" : "w");
+ if (!logfile->fd) {
+ g_free(logfile);
perror(logfilename);
_exit(1);
}
/* In case we are a daemon redirect stderr to logfile */
if (is_daemonized()) {
- dup2(fileno(qemu_logfile), STDERR_FILENO);
- fclose(qemu_logfile);
+ dup2(fileno(logfile->fd), STDERR_FILENO);
+ fclose(logfile->fd);
/* This will skip closing logfile in qemu_log_close() */
- qemu_logfile = stderr;
+ logfile->fd = stderr;
}
} else {
/* Default to stderr if no log file specified */
assert(!is_daemonized());
- qemu_logfile = stderr;
+ logfile->fd = stderr;
}
/* must avoid mmap() usage of glibc by setting a buffer "by hand" */
if (log_uses_own_buffers) {
static char logfile_buf[4096];
- setvbuf(qemu_logfile, logfile_buf, _IOLBF, sizeof(logfile_buf));
+ setvbuf(logfile->fd, logfile_buf, _IOLBF, sizeof(logfile_buf));
} else {
#if defined(_WIN32)
/* Win32 doesn't support line-buffering, so use unbuffered output. */
- setvbuf(qemu_logfile, NULL, _IONBF, 0);
+ setvbuf(logfile->fd, NULL, _IONBF, 0);
#else
- setvbuf(qemu_logfile, NULL, _IOLBF, 0);
+ setvbuf(logfile->fd, NULL, _IOLBF, 0);
#endif
log_append = 1;
}
+ atomic_rcu_set(&qemu_logfile, logfile);
}
- qemu_mutex_unlock(&qemu_logfile_mutex);
+ logfile = qemu_logfile;
+
if (qemu_logfile &&
(is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
- qemu_log_close();
+ atomic_rcu_set(&qemu_logfile, NULL);
+ qemu_mutex_unlock(&qemu_logfile_mutex);
+ call_rcu(logfile, qemu_logfile_free, rcu);
+ } else {
+ qemu_mutex_unlock(&qemu_logfile_mutex);
}
}
@@ -247,17 +262,40 @@ out:
/* fflush() the log file */
void qemu_log_flush(void)
{
- fflush(qemu_logfile);
+ QemuLogFile *logfile;
+
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ fflush(logfile->fd);
+ }
+ rcu_read_unlock();
+}
+
+void qemu_logfile_free(QemuLogFile *logfile)
+{
+ if (logfile) {
+ if (logfile->fd != stderr) {
+ fclose(logfile->fd);
+ }
+ g_free(logfile);
+ }
}
/* Close the log file */
void qemu_log_close(void)
{
- if (qemu_logfile) {
- if (qemu_logfile != stderr) {
- fclose(qemu_logfile);
- }
- qemu_logfile = NULL;
+ QemuLogFile *logfile;
+
+ qemu_mutex_lock(&qemu_logfile_mutex);
+ logfile = qemu_logfile;
+
+ if (logfile) {
+ atomic_rcu_set(&qemu_logfile, NULL);
+ qemu_mutex_unlock(&qemu_logfile_mutex);
+ call_rcu(logfile, qemu_logfile_free, rcu);
+ } else {
+ qemu_mutex_unlock(&qemu_logfile_mutex);
}
}
diff --git a/include/exec/log.h b/include/exec/log.h
index e2cfd436e6..9bd1e4aa20 100644
--- a/include/exec/log.h
+++ b/include/exec/log.h
@@ -15,8 +15,15 @@
*/
static inline void log_cpu_state(CPUState *cpu, int flags)
{
+ QemuLogFile *logfile;
+
if (qemu_log_enabled()) {
- cpu_dump_state(cpu, qemu_logfile, flags);
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ cpu_dump_state(cpu, logfile->fd, flags);
+ }
+ rcu_read_unlock();
}
}
@@ -40,19 +47,37 @@ static inline void log_cpu_state_mask(int mask, CPUState *cpu, int flags)
static inline void log_target_disas(CPUState *cpu, target_ulong start,
target_ulong len)
{
- target_disas(qemu_logfile, cpu, start, len);
+ QemuLogFile *logfile;
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ target_disas(logfile->fd, cpu, start, len);
+ }
+ rcu_read_unlock();
}
static inline void log_disas(void *code, unsigned long size)
{
- disas(qemu_logfile, code, size);
+ QemuLogFile *logfile;
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ disas(logfile->fd, code, size);
+ }
+ rcu_read_unlock();
}
#if defined(CONFIG_USER_ONLY)
/* page_dump() output to the log file: */
static inline void log_page_dump(void)
{
- page_dump(qemu_logfile);
+ QemuLogFile *logfile;
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ page_dump(logfile->fd);
+ }
+ rcu_read_unlock();
}
#endif
#endif
diff --git a/tcg/tcg.c b/tcg/tcg.c
index 5475d49ed1..220eaac7c7 100644
--- a/tcg/tcg.c
+++ b/tcg/tcg.c
@@ -2114,9 +2114,17 @@ static void tcg_dump_ops(TCGContext *s, bool have_prefs)
}
if (have_prefs || op->life) {
- for (; col < 40; ++col) {
- putc(' ', qemu_logfile);
+
+ QemuLogFile *logfile;
+
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ if (logfile) {
+ for (; col < 40; ++col) {
+ putc(' ', logfile->fd);
+ }
}
+ rcu_read_unlock();
}
if (op->life) {
--
2.17.1
^ permalink raw reply related [flat|nested] 19+ messages in thread
* [PATCH 3/4] qemu_log_lock/unlock now preserves the qemu_logfile handle.
2019-11-07 14:26 [PATCH 0/4] Make the qemu_logfile handle thread safe Robert Foley
2019-11-07 14:26 ` [PATCH 1/4] Add a mutex to guarantee single writer to qemu_logfile handle Robert Foley
2019-11-07 14:26 ` [PATCH 2/4] Add use of RCU for qemu_logfile Robert Foley
@ 2019-11-07 14:26 ` Robert Foley
2019-11-07 16:25 ` Alex Bennée
2019-11-07 14:26 ` [PATCH 4/4] Added tests for close and change of logfile Robert Foley
` (2 subsequent siblings)
5 siblings, 1 reply; 19+ messages in thread
From: Robert Foley @ 2019-11-07 14:26 UTC (permalink / raw)
To: qemu-devel; +Cc: peter.puhov, alex.bennee, robert.foley
qemu_log_lock() now returns a handle and qemu_log_unlock() receives a
handle to unlock. This allows for changing the handle during logging
and ensures the lock() and unlock() are for the same file.
Signed-off-by: Robert Foley <robert.foley@linaro.org>
---
include/qemu/log.h | 14 +++++++-------
accel/tcg/cpu-exec.c | 4 ++--
accel/tcg/translate-all.c | 4 ++--
accel/tcg/translator.c | 4 ++--
exec.c | 4 ++--
hw/net/can/can_sja1000.c | 4 ++--
net/can/can_socketcan.c | 5 ++---
target/cris/translate.c | 4 ++--
target/i386/translate.c | 5 +++--
target/lm32/translate.c | 4 ++--
target/microblaze/translate.c | 4 ++--
target/nios2/translate.c | 4 ++--
target/tilegx/translate.c | 7 ++++---
target/unicore32/translate.c | 4 ++--
tcg/tcg.c | 16 ++++++++--------
15 files changed, 44 insertions(+), 43 deletions(-)
diff --git a/include/qemu/log.h b/include/qemu/log.h
index 975de18e23..3d0f47a479 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -71,25 +71,25 @@ static inline bool qemu_log_separate(void)
* qemu_loglevel is never set when qemu_logfile is unset.
*/
-static inline void qemu_log_lock(void)
+static inline FILE *qemu_log_lock(void)
{
QemuLogFile *logfile;
rcu_read_lock();
logfile = atomic_rcu_read(&qemu_logfile);
if (logfile) {
qemu_flockfile(logfile->fd);
+ return logfile->fd;
}
rcu_read_unlock();
+ return NULL;
}
-static inline void qemu_log_unlock(void)
+static inline void qemu_log_unlock(FILE *fd)
{
- QemuLogFile *logfile;
- logfile = atomic_rcu_read(&qemu_logfile);
- if (logfile) {
- qemu_funlockfile(logfile->fd);
+ if (fd) {
+ qemu_funlockfile(fd);
+ rcu_read_unlock();
}
- rcu_read_unlock();
}
/* Logging functions: */
diff --git a/accel/tcg/cpu-exec.c b/accel/tcg/cpu-exec.c
index c01f59c743..62068d10c3 100644
--- a/accel/tcg/cpu-exec.c
+++ b/accel/tcg/cpu-exec.c
@@ -156,7 +156,7 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
#if defined(DEBUG_DISAS)
if (qemu_loglevel_mask(CPU_LOG_TB_CPU)
&& qemu_log_in_addr_range(itb->pc)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
int flags = 0;
if (qemu_loglevel_mask(CPU_LOG_TB_FPU)) {
flags |= CPU_DUMP_FPU;
@@ -165,7 +165,7 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
flags |= CPU_DUMP_CCOP;
#endif
log_cpu_state(cpu, flags);
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif /* DEBUG_DISAS */
diff --git a/accel/tcg/translate-all.c b/accel/tcg/translate-all.c
index 9f48da9472..bb325a2bc4 100644
--- a/accel/tcg/translate-all.c
+++ b/accel/tcg/translate-all.c
@@ -1804,7 +1804,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
#ifdef DEBUG_DISAS
if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM) &&
qemu_log_in_addr_range(tb->pc)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("OUT: [size=%d]\n", gen_code_size);
if (tcg_ctx->data_gen_ptr) {
size_t code_size = tcg_ctx->data_gen_ptr - tb->tc.ptr;
@@ -1829,7 +1829,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
}
qemu_log("\n");
qemu_log_flush();
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
diff --git a/accel/tcg/translator.c b/accel/tcg/translator.c
index f977682be7..603d17ff83 100644
--- a/accel/tcg/translator.c
+++ b/accel/tcg/translator.c
@@ -138,11 +138,11 @@ void translator_loop(const TranslatorOps *ops, DisasContextBase *db,
#ifdef DEBUG_DISAS
if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
&& qemu_log_in_addr_range(db->pc_first)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("----------------\n");
ops->disas_log(db, cpu);
qemu_log("\n");
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
}
diff --git a/exec.c b/exec.c
index ffdb518535..c994a00f10 100644
--- a/exec.c
+++ b/exec.c
@@ -1223,13 +1223,13 @@ void cpu_abort(CPUState *cpu, const char *fmt, ...)
fprintf(stderr, "\n");
cpu_dump_state(cpu, stderr, CPU_DUMP_FPU | CPU_DUMP_CCOP);
if (qemu_log_separate()) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("qemu: fatal: ");
qemu_log_vprintf(fmt, ap2);
qemu_log("\n");
log_cpu_state(cpu, CPU_DUMP_FPU | CPU_DUMP_CCOP);
qemu_log_flush();
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
qemu_log_close();
}
va_end(ap2);
diff --git a/hw/net/can/can_sja1000.c b/hw/net/can/can_sja1000.c
index 1f81341554..39c78faf9b 100644
--- a/hw/net/can/can_sja1000.c
+++ b/hw/net/can/can_sja1000.c
@@ -247,8 +247,8 @@ int can_sja_accept_filter(CanSJA1000State *s,
static void can_display_msg(const char *prefix, const qemu_can_frame *msg)
{
int i;
+ FILE *logfile = qemu_log_lock();
- qemu_log_lock();
qemu_log("%s%03X [%01d] %s %s",
prefix,
msg->can_id & QEMU_CAN_EFF_MASK,
@@ -261,7 +261,7 @@ static void can_display_msg(const char *prefix, const qemu_can_frame *msg)
}
qemu_log("\n");
qemu_log_flush();
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
static void buff2frame_pel(const uint8_t *buff, qemu_can_frame *frame)
diff --git a/net/can/can_socketcan.c b/net/can/can_socketcan.c
index 8a6ffad40c..29bfacd4f8 100644
--- a/net/can/can_socketcan.c
+++ b/net/can/can_socketcan.c
@@ -76,8 +76,7 @@ QEMU_BUILD_BUG_ON(offsetof(qemu_can_frame, data)
static void can_host_socketcan_display_msg(struct qemu_can_frame *msg)
{
int i;
-
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("[cansocketcan]: %03X [%01d] %s %s",
msg->can_id & QEMU_CAN_EFF_MASK,
msg->can_dlc,
@@ -89,7 +88,7 @@ static void can_host_socketcan_display_msg(struct qemu_can_frame *msg)
}
qemu_log("\n");
qemu_log_flush();
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
static void can_host_socketcan_read(void *opaque)
diff --git a/target/cris/translate.c b/target/cris/translate.c
index e752bd0609..cb57516a44 100644
--- a/target/cris/translate.c
+++ b/target/cris/translate.c
@@ -3273,11 +3273,11 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
#if !DISAS_CRIS
if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
&& qemu_log_in_addr_range(pc_start)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("--------------\n");
qemu_log("IN: %s\n", lookup_symbol(pc_start));
log_target_disas(cs, pc_start, dc->pc - pc_start);
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
#endif
diff --git a/target/i386/translate.c b/target/i386/translate.c
index 77e932d827..7c99ef1385 100644
--- a/target/i386/translate.c
+++ b/target/i386/translate.c
@@ -2502,14 +2502,15 @@ static void gen_unknown_opcode(CPUX86State *env, DisasContext *s)
gen_illegal_opcode(s);
if (qemu_loglevel_mask(LOG_UNIMP)) {
+ FILE *logfile = qemu_log_lock();
target_ulong pc = s->pc_start, end = s->pc;
- qemu_log_lock();
+
qemu_log("ILLOPC: " TARGET_FMT_lx ":", pc);
for (; pc < end; ++pc) {
qemu_log(" %02x", cpu_ldub_code(env, pc));
}
qemu_log("\n");
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
}
diff --git a/target/lm32/translate.c b/target/lm32/translate.c
index 778cae1e81..73db9654d6 100644
--- a/target/lm32/translate.c
+++ b/target/lm32/translate.c
@@ -1137,10 +1137,10 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
#ifdef DEBUG_DISAS
if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
&& qemu_log_in_addr_range(pc_start)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("\n");
log_target_disas(cs, pc_start, dc->pc - pc_start);
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
}
diff --git a/target/microblaze/translate.c b/target/microblaze/translate.c
index 761f535357..cc1ad15656 100644
--- a/target/microblaze/translate.c
+++ b/target/microblaze/translate.c
@@ -1766,10 +1766,10 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
#if !SIM_COMPAT
if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
&& qemu_log_in_addr_range(pc_start)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("--------------\n");
log_target_disas(cs, pc_start, dc->pc - pc_start);
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
#endif
diff --git a/target/nios2/translate.c b/target/nios2/translate.c
index e17656e66f..82107bf270 100644
--- a/target/nios2/translate.c
+++ b/target/nios2/translate.c
@@ -892,11 +892,11 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
#ifdef DEBUG_DISAS
if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
&& qemu_log_in_addr_range(tb->pc)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("IN: %s\n", lookup_symbol(tb->pc));
log_target_disas(cs, tb->pc, dc->pc - tb->pc);
qemu_log("\n");
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
}
diff --git a/target/tilegx/translate.c b/target/tilegx/translate.c
index 68dd4aa2d8..fd406f4f71 100644
--- a/target/tilegx/translate.c
+++ b/target/tilegx/translate.c
@@ -2377,6 +2377,7 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
uint64_t pc_start = tb->pc;
uint64_t page_start = pc_start & TARGET_PAGE_MASK;
int num_insns = 0;
+ FILE *logfile = NULL;
dc->pc = pc_start;
dc->mmuidx = 0;
@@ -2388,7 +2389,7 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
dc->zero = NULL;
if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)) {
- qemu_log_lock();
+ logfile = qemu_log_lock();
qemu_log("IN: %s\n", lookup_symbol(pc_start));
}
gen_tb_start(tb);
@@ -2418,9 +2419,9 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
tb->size = dc->pc - pc_start;
tb->icount = num_insns;
- if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)) {
+ if (logfile) {
qemu_log("\n");
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
}
diff --git a/target/unicore32/translate.c b/target/unicore32/translate.c
index 0e01f35856..0f6891b8aa 100644
--- a/target/unicore32/translate.c
+++ b/target/unicore32/translate.c
@@ -1994,12 +1994,12 @@ done_generating:
#ifdef DEBUG_DISAS
if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
&& qemu_log_in_addr_range(pc_start)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("----------------\n");
qemu_log("IN: %s\n", lookup_symbol(pc_start));
log_target_disas(cs, pc_start, dc->pc - pc_start);
qemu_log("\n");
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
tb->size = dc->pc - pc_start;
diff --git a/tcg/tcg.c b/tcg/tcg.c
index 220eaac7c7..4f616ba38b 100644
--- a/tcg/tcg.c
+++ b/tcg/tcg.c
@@ -1085,7 +1085,7 @@ void tcg_prologue_init(TCGContext *s)
#ifdef DEBUG_DISAS
if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM)) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("PROLOGUE: [size=%zu]\n", prologue_size);
if (s->data_gen_ptr) {
size_t code_size = s->data_gen_ptr - buf0;
@@ -1110,7 +1110,7 @@ void tcg_prologue_init(TCGContext *s)
}
qemu_log("\n");
qemu_log_flush();
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
@@ -4049,11 +4049,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
#ifdef DEBUG_DISAS
if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP)
&& qemu_log_in_addr_range(tb->pc))) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("OP:\n");
tcg_dump_ops(s, false);
qemu_log("\n");
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
@@ -4094,11 +4094,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
#ifdef DEBUG_DISAS
if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP_IND)
&& qemu_log_in_addr_range(tb->pc))) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("OP before indirect lowering:\n");
tcg_dump_ops(s, false);
qemu_log("\n");
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
/* Replace indirect temps with direct temps. */
@@ -4115,11 +4115,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
#ifdef DEBUG_DISAS
if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP_OPT)
&& qemu_log_in_addr_range(tb->pc))) {
- qemu_log_lock();
+ FILE *logfile = qemu_log_lock();
qemu_log("OP after optimization and liveness analysis:\n");
tcg_dump_ops(s, true);
qemu_log("\n");
- qemu_log_unlock();
+ qemu_log_unlock(logfile);
}
#endif
--
2.17.1
^ permalink raw reply related [flat|nested] 19+ messages in thread
* [PATCH 4/4] Added tests for close and change of logfile.
2019-11-07 14:26 [PATCH 0/4] Make the qemu_logfile handle thread safe Robert Foley
` (2 preceding siblings ...)
2019-11-07 14:26 ` [PATCH 3/4] qemu_log_lock/unlock now preserves the qemu_logfile handle Robert Foley
@ 2019-11-07 14:26 ` Robert Foley
2019-11-07 16:32 ` Alex Bennée
2019-11-07 14:46 ` [PATCH 0/4] Make the qemu_logfile handle thread safe no-reply
2019-11-07 16:35 ` Alex Bennée
5 siblings, 1 reply; 19+ messages in thread
From: Robert Foley @ 2019-11-07 14:26 UTC (permalink / raw)
To: qemu-devel; +Cc: peter.puhov, alex.bennee, robert.foley
One test ensures that the logfile handle is still valid even if
the logfile is changed during logging.
The other test validates that the logfile handle remains valid under
the logfile lock even if the logfile is closed.
Signed-off-by: Robert Foley <robert.foley@linaro.org>
---
tests/test-logging.c | 74 ++++++++++++++++++++++++++++++++++++++++++++
1 file changed, 74 insertions(+)
diff --git a/tests/test-logging.c b/tests/test-logging.c
index a12585f70a..a3190ff92c 100644
--- a/tests/test-logging.c
+++ b/tests/test-logging.c
@@ -108,6 +108,76 @@ static void test_parse_path(gconstpointer data)
error_free_or_abort(&err);
}
+static void test_logfile_write(gconstpointer data)
+{
+ QemuLogFile *logfile;
+ gchar const *dir = data;
+ Error *err = NULL;
+ gchar *file_path;
+ gchar *file_path1;
+ FILE *orig_fd;
+
+ file_path = g_build_filename(dir, "qemu_test_log_write0.log", NULL);
+ file_path1 = g_build_filename(dir, "qemu_test_log_write1.log", NULL);
+
+ /*
+ * Test that even if an open file handle is changed,
+ * our handle remains valid due to RCU.
+ */
+ qemu_set_log_filename(file_path, &err);
+ g_assert(!err);
+ rcu_read_lock();
+ logfile = atomic_rcu_read(&qemu_logfile);
+ orig_fd = logfile->fd;
+ g_assert(logfile && logfile->fd);
+ fprintf(logfile->fd, "%s 1st write to file\n", __func__);
+ fflush(logfile->fd);
+
+ /* Change the logfile and ensure that the handle is still valid. */
+ qemu_set_log_filename(file_path1, &err);
+ g_assert(!err);
+ g_assert(logfile->fd == orig_fd);
+ fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
+ fflush(logfile->fd);
+ rcu_read_unlock();
+
+ g_free(file_path);
+ g_free(file_path1);
+}
+
+static void test_logfile_lock(gconstpointer data)
+{
+ FILE *logfile;
+ gchar const *dir = data;
+ Error *err = NULL;
+ gchar *file_path;
+
+ file_path = g_build_filename(dir, "qemu_test_logfile_lock0.log", NULL);
+
+ /*
+ * Test the use of the logfile lock, such
+ * that even if an open file handle is closed,
+ * our handle remains valid for use due to RCU.
+ */
+ qemu_set_log_filename(file_path, &err);
+ logfile = qemu_log_lock();
+ g_assert(logfile);
+ fprintf(logfile, "%s 1st write to file\n", __func__);
+ fflush(logfile);
+
+ /*
+ * Initiate a close file and make sure our handle remains
+ * valid since we still have the logfile lock.
+ */
+ qemu_log_close();
+ fprintf(logfile, "%s 2nd write to file\n", __func__);
+ fflush(logfile);
+ qemu_log_unlock(logfile);
+
+ g_assert(!err);
+ g_free(file_path);
+}
+
/* Remove a directory and all its entries (non-recursive). */
static void rmdir_full(gchar const *root)
{
@@ -134,6 +204,10 @@ int main(int argc, char **argv)
g_test_add_func("/logging/parse_range", test_parse_range);
g_test_add_data_func("/logging/parse_path", tmp_path, test_parse_path);
+ g_test_add_data_func("/logging/logfile_write_path",
+ tmp_path, test_logfile_write);
+ g_test_add_data_func("/logging/logfile_lock_path",
+ tmp_path, test_logfile_lock);
rc = g_test_run();
--
2.17.1
^ permalink raw reply related [flat|nested] 19+ messages in thread
* Re: [PATCH 0/4] Make the qemu_logfile handle thread safe.
2019-11-07 14:26 [PATCH 0/4] Make the qemu_logfile handle thread safe Robert Foley
` (3 preceding siblings ...)
2019-11-07 14:26 ` [PATCH 4/4] Added tests for close and change of logfile Robert Foley
@ 2019-11-07 14:46 ` no-reply
2019-11-07 16:35 ` Alex Bennée
5 siblings, 0 replies; 19+ messages in thread
From: no-reply @ 2019-11-07 14:46 UTC (permalink / raw)
To: robert.foley; +Cc: peter.puhov, alex.bennee, qemu-devel, robert.foley
Patchew URL: https://patchew.org/QEMU/20191107142613.2379-1-robert.foley@linaro.org/
Hi,
This series failed the docker-quick@centos7 build test. Please find the testing commands and
their output below. If you have Docker installed, you can probably reproduce it
locally.
=== TEST SCRIPT BEGIN ===
#!/bin/bash
make docker-image-centos7 V=1 NETWORK=1
time make docker-test-quick@centos7 SHOW_ENV=1 J=14 NETWORK=1
=== TEST SCRIPT END ===
TEST check-unit: tests/test-hbitmap
TEST check-unit: tests/test-bdrv-drain
test-bdrv-drain: /tmp/qemu-test/src/util/async.c:283: aio_ctx_finalize: Assertion `!qemu_lockcnt_count(&ctx->list_lock)' failed.
ERROR - too few tests run (expected 42, got 17)
make: *** [check-unit] Error 1
make: *** Waiting for unfinished jobs....
TEST iotest-qcow2: 013
TEST iotest-qcow2: 017
---
raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['sudo', '-n', 'docker', 'run', '--label', 'com.qemu.instance.uuid=eaa57e3449fb433ebde0eceb9d05b6c2', '-u', '1003', '--security-opt', 'seccomp=unconfined', '--rm', '-e', 'TARGET_LIST=', '-e', 'EXTRA_CONFIGURE_OPTS=', '-e', 'V=', '-e', 'J=14', '-e', 'DEBUG=', '-e', 'SHOW_ENV=1', '-e', 'CCACHE_DIR=/var/tmp/ccache', '-v', '/home/patchew2/.cache/qemu-docker-ccache:/var/tmp/ccache:z', '-v', '/var/tmp/patchew-tester-tmp-xw43l1zq/src/docker-src.2019-11-07-09.34.09.25341:/var/tmp/qemu:z,ro', 'qemu:centos7', '/var/tmp/qemu/run', 'test-quick']' returned non-zero exit status 2.
filter=--filter=label=com.qemu.instance.uuid=eaa57e3449fb433ebde0eceb9d05b6c2
make[1]: *** [docker-run] Error 1
make[1]: Leaving directory `/var/tmp/patchew-tester-tmp-xw43l1zq/src'
make: *** [docker-run-test-quick@centos7] Error 2
real 12m39.833s
user 0m8.137s
The full log is available at
http://patchew.org/logs/20191107142613.2379-1-robert.foley@linaro.org/testing.docker-quick@centos7/?type=message.
---
Email generated automatically by Patchew [https://patchew.org/].
Please send your feedback to patchew-devel@redhat.com
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 2/4] Add use of RCU for qemu_logfile.
2019-11-07 14:26 ` [PATCH 2/4] Add use of RCU for qemu_logfile Robert Foley
@ 2019-11-07 16:23 ` Alex Bennée
2019-11-07 21:13 ` Robert Foley
0 siblings, 1 reply; 19+ messages in thread
From: Alex Bennée @ 2019-11-07 16:23 UTC (permalink / raw)
To: Robert Foley; +Cc: peter.puhov, qemu-devel
Robert Foley <robert.foley@linaro.org> writes:
> This now allows changing the logfile while logging is active,
> and also solves the issue of a seg fault while changing the logfile.
>
> Any read access to the qemu_logfile handle will use
> the rcu_read_lock()/unlock() around the use of the handle.
> To fetch the handle we will use atomic_rcu_read().
> We also in many cases do a check for validity of the
> logfile handle before using it to deal with the case where the
> file is closed and set to NULL.
>
> The cases where we write to the qemu_logfile will use atomic_rcu_set().
> Writers will also use call_rcu() with a newly added qemu_logfile_free
> function for freeing/closing when readers have finished.
>
> Signed-off-by: Robert Foley <robert.foley@linaro.org>
> ---
> include/qemu/log.h | 47 ++++++++++++++++++++++++----
> util/log.c | 78 ++++++++++++++++++++++++++++++++++------------
> include/exec/log.h | 33 +++++++++++++++++---
> tcg/tcg.c | 12 +++++--
> 4 files changed, 138 insertions(+), 32 deletions(-)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index a91105b2ad..975de18e23 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -3,9 +3,17 @@
>
> /* A small part of this API is split into its own header */
> #include "qemu/log-for-trace.h"
> +#include "qemu/rcu.h"
> +
> +struct QemuLogFile {
> + struct rcu_head rcu;
> + FILE *fd;
> +};
> +typedef struct QemuLogFile QemuLogFile;
If you are declaring a typedef then do it in one:
typedef struct QemuLogFile { ...
We only really use the second form for opaque structs where the handle
is passed around but the contents hidden from the rest of QEMU.
>
> /* Private global variable, don't use */
> -extern FILE *qemu_logfile;
> +extern QemuLogFile *qemu_logfile;
> +
Do we need multiple
>
> /*
> * The new API:
> @@ -25,7 +33,17 @@ static inline bool qemu_log_enabled(void)
> */
> static inline bool qemu_log_separate(void)
> {
> - return qemu_logfile != NULL && qemu_logfile != stderr;
> + QemuLogFile *logfile;
> +
> + if (qemu_log_enabled()) {
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile && logfile->fd != stderr) {
> + return true;
> + }
> + rcu_read_unlock();
> + }
> + return false;
This is unbalanced as you'll have incremented the reader count. Also
qemu_log_enabled() is also synonymous with logfile existing so you could
fold that into:
bool res = false;
rcu_read_lock();
*logfile = atomic_rcu_read(&qemu_logfile);
if (logfile && logfile->fd != stderr) {
res = true;
}
rcu_read_unlock();
return res;
There is technically a race there as the answer may become invalid after
qemu_log_separate() returns. However given the users I don't see what
could fail afterwards.
> }
>
> #define CPU_LOG_TB_OUT_ASM (1 << 0)
> @@ -55,12 +73,23 @@ static inline bool qemu_log_separate(void)
>
> static inline void qemu_log_lock(void)
> {
> - qemu_flockfile(qemu_logfile);
> + QemuLogFile *logfile;
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile) {
> + qemu_flockfile(logfile->fd);
> + }
> + rcu_read_unlock();
> }
static inline FILE *fd qemu_log_lock(void)
{
FILE *fd;
rcu_read_lock();
fd = atomic_rcu_read(&qemu_logfile);
if (fd) {
qemu_flockfile(fd);
return fd;
} else {
rcu_read_unlock();
return NULL;
}
}
static inline qemu_log_unlock(FILE *fd)
{
if (fd) {
qemu_funlockfile(fd);
rcu_read_unlock();
}
}
While the rcu_read_lock() is in progress then we won't ever finish with
the fd - which we don't want to do until the file locking is finished.
<snip>
>
> /* Logging functions: */
> @@ -70,9 +99,14 @@ static inline void qemu_log_unlock(void)
> static inline void GCC_FMT_ATTR(1, 0)
> qemu_log_vprintf(const char *fmt, va_list va)
> {
> - if (qemu_logfile) {
> - vfprintf(qemu_logfile, fmt, va);
> + QemuLogFile *logfile;
> +
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile) {
> + vfprintf(logfile->fd, fmt, va);
> }
> + rcu_read_unlock();
> }
>
> /* log only if a bit is set on the current loglevel mask:
> @@ -129,5 +163,6 @@ void qemu_print_log_usage(FILE *f);
> void qemu_log_flush(void);
> /* Close the log file */
> void qemu_log_close(void);
> +void qemu_logfile_free(QemuLogFile *logfile);
>
> #endif
> diff --git a/util/log.c b/util/log.c
> index dff2f98c8c..d409532b8f 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -29,7 +29,7 @@
> static char *logfilename;
> static bool qemu_logfile_initialized;
> static QemuMutex qemu_logfile_mutex;
> -FILE *qemu_logfile;
> +QemuLogFile *qemu_logfile;
> int qemu_loglevel;
> static int log_append = 0;
> static GArray *debug_regions;
> @@ -38,10 +38,14 @@ static GArray *debug_regions;
> int qemu_log(const char *fmt, ...)
> {
> int ret = 0;
> - if (qemu_logfile) {
> + QemuLogFile *logfile;
> +
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile) {
> va_list ap;
> va_start(ap, fmt);
> - ret = vfprintf(qemu_logfile, fmt, ap);
> + ret = vfprintf(logfile->fd, fmt, ap);
> va_end(ap);
>
> /* Don't pass back error results. */
> @@ -49,6 +53,7 @@ int qemu_log(const char *fmt, ...)
> ret = 0;
> }
> }
> + rcu_read_unlock();
> return ret;
> }
>
> @@ -65,6 +70,8 @@ static bool log_uses_own_buffers;
> /* enable or disable low levels log */
> void qemu_set_log(int log_flags)
> {
> + QemuLogFile *logfile;
> +
> qemu_loglevel = log_flags;
> #ifdef CONFIG_TRACE_LOG
> qemu_loglevel |= LOG_TRACE;
> @@ -77,43 +84,51 @@ void qemu_set_log(int log_flags)
> qemu_mutex_lock(&qemu_logfile_mutex);
> if (!qemu_logfile &&
> (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
> + logfile = g_new0(QemuLogFile, 1);
> if (logfilename) {
You can assume logfilename exists as glib memory allocations would
abort() otherwise.
> - qemu_logfile = fopen(logfilename, log_append ? "a" : "w");
> - if (!qemu_logfile) {
> + logfile->fd = fopen(logfilename, log_append ? "a" : "w");
> + if (!logfile->fd) {
> + g_free(logfile);
> perror(logfilename);
> _exit(1);
> }
> /* In case we are a daemon redirect stderr to logfile */
> if (is_daemonized()) {
> - dup2(fileno(qemu_logfile), STDERR_FILENO);
> - fclose(qemu_logfile);
> + dup2(fileno(logfile->fd), STDERR_FILENO);
> + fclose(logfile->fd);
> /* This will skip closing logfile in qemu_log_close() */
> - qemu_logfile = stderr;
> + logfile->fd = stderr;
> }
> } else {
> /* Default to stderr if no log file specified */
> assert(!is_daemonized());
> - qemu_logfile = stderr;
> + logfile->fd = stderr;
> }
> /* must avoid mmap() usage of glibc by setting a buffer "by hand" */
> if (log_uses_own_buffers) {
> static char logfile_buf[4096];
>
> - setvbuf(qemu_logfile, logfile_buf, _IOLBF, sizeof(logfile_buf));
> + setvbuf(logfile->fd, logfile_buf, _IOLBF, sizeof(logfile_buf));
> } else {
> #if defined(_WIN32)
> /* Win32 doesn't support line-buffering, so use unbuffered output. */
> - setvbuf(qemu_logfile, NULL, _IONBF, 0);
> + setvbuf(logfile->fd, NULL, _IONBF, 0);
> #else
> - setvbuf(qemu_logfile, NULL, _IOLBF, 0);
> + setvbuf(logfile->fd, NULL, _IOLBF, 0);
> #endif
> log_append = 1;
> }
> + atomic_rcu_set(&qemu_logfile, logfile);
> }
> - qemu_mutex_unlock(&qemu_logfile_mutex);
> + logfile = qemu_logfile;
> +
> if (qemu_logfile &&
> (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
> - qemu_log_close();
> + atomic_rcu_set(&qemu_logfile, NULL);
> + qemu_mutex_unlock(&qemu_logfile_mutex);
> + call_rcu(logfile, qemu_logfile_free, rcu);
> + } else {
> + qemu_mutex_unlock(&qemu_logfile_mutex);
> }
> }
>
> @@ -247,17 +262,40 @@ out:
> /* fflush() the log file */
> void qemu_log_flush(void)
> {
> - fflush(qemu_logfile);
> + QemuLogFile *logfile;
> +
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile) {
> + fflush(logfile->fd);
> + }
> + rcu_read_unlock();
> +}
> +
> +void qemu_logfile_free(QemuLogFile *logfile)
This can be static as it's internal to log.c
> +{
> + if (logfile) {
g_assert(logfile) instead of the if?
> + if (logfile->fd != stderr) {
> + fclose(logfile->fd);
> + }
> + g_free(logfile);
> + }
> }
>
> /* Close the log file */
> void qemu_log_close(void)
> {
> - if (qemu_logfile) {
> - if (qemu_logfile != stderr) {
> - fclose(qemu_logfile);
> - }
> - qemu_logfile = NULL;
> + QemuLogFile *logfile;
> +
> + qemu_mutex_lock(&qemu_logfile_mutex);
> + logfile = qemu_logfile;
> +
> + if (logfile) {
> + atomic_rcu_set(&qemu_logfile, NULL);
> + qemu_mutex_unlock(&qemu_logfile_mutex);
I think you can move the both the unlocks out of the if/else and drop
the else.
> + call_rcu(logfile, qemu_logfile_free, rcu);
> + } else {
> + qemu_mutex_unlock(&qemu_logfile_mutex);
> }
> }
>
> diff --git a/include/exec/log.h b/include/exec/log.h
> index e2cfd436e6..9bd1e4aa20 100644
> --- a/include/exec/log.h
> +++ b/include/exec/log.h
> @@ -15,8 +15,15 @@
> */
> static inline void log_cpu_state(CPUState *cpu, int flags)
> {
> + QemuLogFile *logfile;
> +
> if (qemu_log_enabled()) {
> - cpu_dump_state(cpu, qemu_logfile, flags);
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile) {
> + cpu_dump_state(cpu, logfile->fd, flags);
> + }
> + rcu_read_unlock();
> }
> }
>
> @@ -40,19 +47,37 @@ static inline void log_cpu_state_mask(int mask, CPUState *cpu, int flags)
> static inline void log_target_disas(CPUState *cpu, target_ulong start,
> target_ulong len)
> {
> - target_disas(qemu_logfile, cpu, start, len);
> + QemuLogFile *logfile;
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile) {
> + target_disas(logfile->fd, cpu, start, len);
> + }
> + rcu_read_unlock();
> }
>
> static inline void log_disas(void *code, unsigned long size)
> {
> - disas(qemu_logfile, code, size);
> + QemuLogFile *logfile;
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile) {
> + disas(logfile->fd, code, size);
> + }
> + rcu_read_unlock();
> }
>
> #if defined(CONFIG_USER_ONLY)
> /* page_dump() output to the log file: */
> static inline void log_page_dump(void)
> {
> - page_dump(qemu_logfile);
> + QemuLogFile *logfile;
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + if (logfile) {
> + page_dump(logfile->fd);
> + }
> + rcu_read_unlock();
> }
> #endif
> #endif
> diff --git a/tcg/tcg.c b/tcg/tcg.c
> index 5475d49ed1..220eaac7c7 100644
> --- a/tcg/tcg.c
> +++ b/tcg/tcg.c
> @@ -2114,9 +2114,17 @@ static void tcg_dump_ops(TCGContext *s, bool have_prefs)
> }
>
> if (have_prefs || op->life) {
> - for (; col < 40; ++col) {
> - putc(' ', qemu_logfile);
> +
> + QemuLogFile *logfile;
> +
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
This can probably be a qemu_log_lock() instead given interleaving output
is going to be confusing.
> + if (logfile) {
> + for (; col < 40; ++col) {
> + putc(' ', logfile->fd);
> + }
> }
> + rcu_read_unlock();
and qemu_log_unlock();
This cleanup could even be in a separate patch.
> }
>
> if (op->life) {
--
Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 3/4] qemu_log_lock/unlock now preserves the qemu_logfile handle.
2019-11-07 14:26 ` [PATCH 3/4] qemu_log_lock/unlock now preserves the qemu_logfile handle Robert Foley
@ 2019-11-07 16:25 ` Alex Bennée
2019-11-07 21:22 ` Robert Foley
0 siblings, 1 reply; 19+ messages in thread
From: Alex Bennée @ 2019-11-07 16:25 UTC (permalink / raw)
To: Robert Foley; +Cc: peter.puhov, qemu-devel
Robert Foley <robert.foley@linaro.org> writes:
> qemu_log_lock() now returns a handle and qemu_log_unlock() receives a
> handle to unlock. This allows for changing the handle during logging
> and ensures the lock() and unlock() are for the same file.
Ahh there it is!
We probably want to put the API change through before we add the RCU
support - so swap the patch order around.
>
> Signed-off-by: Robert Foley <robert.foley@linaro.org>
> ---
> include/qemu/log.h | 14 +++++++-------
> accel/tcg/cpu-exec.c | 4 ++--
> accel/tcg/translate-all.c | 4 ++--
> accel/tcg/translator.c | 4 ++--
> exec.c | 4 ++--
> hw/net/can/can_sja1000.c | 4 ++--
> net/can/can_socketcan.c | 5 ++---
> target/cris/translate.c | 4 ++--
> target/i386/translate.c | 5 +++--
> target/lm32/translate.c | 4 ++--
> target/microblaze/translate.c | 4 ++--
> target/nios2/translate.c | 4 ++--
> target/tilegx/translate.c | 7 ++++---
> target/unicore32/translate.c | 4 ++--
> tcg/tcg.c | 16 ++++++++--------
> 15 files changed, 44 insertions(+), 43 deletions(-)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index 975de18e23..3d0f47a479 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -71,25 +71,25 @@ static inline bool qemu_log_separate(void)
> * qemu_loglevel is never set when qemu_logfile is unset.
> */
>
> -static inline void qemu_log_lock(void)
> +static inline FILE *qemu_log_lock(void)
> {
> QemuLogFile *logfile;
> rcu_read_lock();
> logfile = atomic_rcu_read(&qemu_logfile);
> if (logfile) {
> qemu_flockfile(logfile->fd);
> + return logfile->fd;
> }
> rcu_read_unlock();
> + return NULL;
> }
>
> -static inline void qemu_log_unlock(void)
> +static inline void qemu_log_unlock(FILE *fd)
> {
> - QemuLogFile *logfile;
> - logfile = atomic_rcu_read(&qemu_logfile);
> - if (logfile) {
> - qemu_funlockfile(logfile->fd);
> + if (fd) {
> + qemu_funlockfile(fd);
> + rcu_read_unlock();
> }
> - rcu_read_unlock();
> }
>
> /* Logging functions: */
> diff --git a/accel/tcg/cpu-exec.c b/accel/tcg/cpu-exec.c
> index c01f59c743..62068d10c3 100644
> --- a/accel/tcg/cpu-exec.c
> +++ b/accel/tcg/cpu-exec.c
> @@ -156,7 +156,7 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
> #if defined(DEBUG_DISAS)
> if (qemu_loglevel_mask(CPU_LOG_TB_CPU)
> && qemu_log_in_addr_range(itb->pc)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> int flags = 0;
> if (qemu_loglevel_mask(CPU_LOG_TB_FPU)) {
> flags |= CPU_DUMP_FPU;
> @@ -165,7 +165,7 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
> flags |= CPU_DUMP_CCOP;
> #endif
> log_cpu_state(cpu, flags);
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif /* DEBUG_DISAS */
>
> diff --git a/accel/tcg/translate-all.c b/accel/tcg/translate-all.c
> index 9f48da9472..bb325a2bc4 100644
> --- a/accel/tcg/translate-all.c
> +++ b/accel/tcg/translate-all.c
> @@ -1804,7 +1804,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
> #ifdef DEBUG_DISAS
> if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM) &&
> qemu_log_in_addr_range(tb->pc)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("OUT: [size=%d]\n", gen_code_size);
> if (tcg_ctx->data_gen_ptr) {
> size_t code_size = tcg_ctx->data_gen_ptr - tb->tc.ptr;
> @@ -1829,7 +1829,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
> }
> qemu_log("\n");
> qemu_log_flush();
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
>
> diff --git a/accel/tcg/translator.c b/accel/tcg/translator.c
> index f977682be7..603d17ff83 100644
> --- a/accel/tcg/translator.c
> +++ b/accel/tcg/translator.c
> @@ -138,11 +138,11 @@ void translator_loop(const TranslatorOps *ops, DisasContextBase *db,
> #ifdef DEBUG_DISAS
> if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> && qemu_log_in_addr_range(db->pc_first)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("----------------\n");
> ops->disas_log(db, cpu);
> qemu_log("\n");
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
> }
> diff --git a/exec.c b/exec.c
> index ffdb518535..c994a00f10 100644
> --- a/exec.c
> +++ b/exec.c
> @@ -1223,13 +1223,13 @@ void cpu_abort(CPUState *cpu, const char *fmt, ...)
> fprintf(stderr, "\n");
> cpu_dump_state(cpu, stderr, CPU_DUMP_FPU | CPU_DUMP_CCOP);
> if (qemu_log_separate()) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("qemu: fatal: ");
> qemu_log_vprintf(fmt, ap2);
> qemu_log("\n");
> log_cpu_state(cpu, CPU_DUMP_FPU | CPU_DUMP_CCOP);
> qemu_log_flush();
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> qemu_log_close();
> }
> va_end(ap2);
> diff --git a/hw/net/can/can_sja1000.c b/hw/net/can/can_sja1000.c
> index 1f81341554..39c78faf9b 100644
> --- a/hw/net/can/can_sja1000.c
> +++ b/hw/net/can/can_sja1000.c
> @@ -247,8 +247,8 @@ int can_sja_accept_filter(CanSJA1000State *s,
> static void can_display_msg(const char *prefix, const qemu_can_frame *msg)
> {
> int i;
> + FILE *logfile = qemu_log_lock();
>
> - qemu_log_lock();
> qemu_log("%s%03X [%01d] %s %s",
> prefix,
> msg->can_id & QEMU_CAN_EFF_MASK,
> @@ -261,7 +261,7 @@ static void can_display_msg(const char *prefix, const qemu_can_frame *msg)
> }
> qemu_log("\n");
> qemu_log_flush();
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
>
> static void buff2frame_pel(const uint8_t *buff, qemu_can_frame *frame)
> diff --git a/net/can/can_socketcan.c b/net/can/can_socketcan.c
> index 8a6ffad40c..29bfacd4f8 100644
> --- a/net/can/can_socketcan.c
> +++ b/net/can/can_socketcan.c
> @@ -76,8 +76,7 @@ QEMU_BUILD_BUG_ON(offsetof(qemu_can_frame, data)
> static void can_host_socketcan_display_msg(struct qemu_can_frame *msg)
> {
> int i;
> -
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("[cansocketcan]: %03X [%01d] %s %s",
> msg->can_id & QEMU_CAN_EFF_MASK,
> msg->can_dlc,
> @@ -89,7 +88,7 @@ static void can_host_socketcan_display_msg(struct qemu_can_frame *msg)
> }
> qemu_log("\n");
> qemu_log_flush();
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
>
> static void can_host_socketcan_read(void *opaque)
> diff --git a/target/cris/translate.c b/target/cris/translate.c
> index e752bd0609..cb57516a44 100644
> --- a/target/cris/translate.c
> +++ b/target/cris/translate.c
> @@ -3273,11 +3273,11 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> #if !DISAS_CRIS
> if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> && qemu_log_in_addr_range(pc_start)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("--------------\n");
> qemu_log("IN: %s\n", lookup_symbol(pc_start));
> log_target_disas(cs, pc_start, dc->pc - pc_start);
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
> #endif
> diff --git a/target/i386/translate.c b/target/i386/translate.c
> index 77e932d827..7c99ef1385 100644
> --- a/target/i386/translate.c
> +++ b/target/i386/translate.c
> @@ -2502,14 +2502,15 @@ static void gen_unknown_opcode(CPUX86State *env, DisasContext *s)
> gen_illegal_opcode(s);
>
> if (qemu_loglevel_mask(LOG_UNIMP)) {
> + FILE *logfile = qemu_log_lock();
> target_ulong pc = s->pc_start, end = s->pc;
> - qemu_log_lock();
> +
> qemu_log("ILLOPC: " TARGET_FMT_lx ":", pc);
> for (; pc < end; ++pc) {
> qemu_log(" %02x", cpu_ldub_code(env, pc));
> }
> qemu_log("\n");
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> }
>
> diff --git a/target/lm32/translate.c b/target/lm32/translate.c
> index 778cae1e81..73db9654d6 100644
> --- a/target/lm32/translate.c
> +++ b/target/lm32/translate.c
> @@ -1137,10 +1137,10 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> #ifdef DEBUG_DISAS
> if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> && qemu_log_in_addr_range(pc_start)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("\n");
> log_target_disas(cs, pc_start, dc->pc - pc_start);
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
> }
> diff --git a/target/microblaze/translate.c b/target/microblaze/translate.c
> index 761f535357..cc1ad15656 100644
> --- a/target/microblaze/translate.c
> +++ b/target/microblaze/translate.c
> @@ -1766,10 +1766,10 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> #if !SIM_COMPAT
> if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> && qemu_log_in_addr_range(pc_start)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("--------------\n");
> log_target_disas(cs, pc_start, dc->pc - pc_start);
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
> #endif
> diff --git a/target/nios2/translate.c b/target/nios2/translate.c
> index e17656e66f..82107bf270 100644
> --- a/target/nios2/translate.c
> +++ b/target/nios2/translate.c
> @@ -892,11 +892,11 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> #ifdef DEBUG_DISAS
> if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> && qemu_log_in_addr_range(tb->pc)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("IN: %s\n", lookup_symbol(tb->pc));
> log_target_disas(cs, tb->pc, dc->pc - tb->pc);
> qemu_log("\n");
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
> }
> diff --git a/target/tilegx/translate.c b/target/tilegx/translate.c
> index 68dd4aa2d8..fd406f4f71 100644
> --- a/target/tilegx/translate.c
> +++ b/target/tilegx/translate.c
> @@ -2377,6 +2377,7 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> uint64_t pc_start = tb->pc;
> uint64_t page_start = pc_start & TARGET_PAGE_MASK;
> int num_insns = 0;
> + FILE *logfile = NULL;
>
> dc->pc = pc_start;
> dc->mmuidx = 0;
> @@ -2388,7 +2389,7 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> dc->zero = NULL;
>
> if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)) {
> - qemu_log_lock();
> + logfile = qemu_log_lock();
> qemu_log("IN: %s\n", lookup_symbol(pc_start));
> }
> gen_tb_start(tb);
> @@ -2418,9 +2419,9 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> tb->size = dc->pc - pc_start;
> tb->icount = num_insns;
>
> - if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)) {
> + if (logfile) {
> qemu_log("\n");
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> }
>
> diff --git a/target/unicore32/translate.c b/target/unicore32/translate.c
> index 0e01f35856..0f6891b8aa 100644
> --- a/target/unicore32/translate.c
> +++ b/target/unicore32/translate.c
> @@ -1994,12 +1994,12 @@ done_generating:
> #ifdef DEBUG_DISAS
> if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> && qemu_log_in_addr_range(pc_start)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("----------------\n");
> qemu_log("IN: %s\n", lookup_symbol(pc_start));
> log_target_disas(cs, pc_start, dc->pc - pc_start);
> qemu_log("\n");
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
> tb->size = dc->pc - pc_start;
> diff --git a/tcg/tcg.c b/tcg/tcg.c
> index 220eaac7c7..4f616ba38b 100644
> --- a/tcg/tcg.c
> +++ b/tcg/tcg.c
> @@ -1085,7 +1085,7 @@ void tcg_prologue_init(TCGContext *s)
>
> #ifdef DEBUG_DISAS
> if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM)) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("PROLOGUE: [size=%zu]\n", prologue_size);
> if (s->data_gen_ptr) {
> size_t code_size = s->data_gen_ptr - buf0;
> @@ -1110,7 +1110,7 @@ void tcg_prologue_init(TCGContext *s)
> }
> qemu_log("\n");
> qemu_log_flush();
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
>
> @@ -4049,11 +4049,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
> #ifdef DEBUG_DISAS
> if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP)
> && qemu_log_in_addr_range(tb->pc))) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("OP:\n");
> tcg_dump_ops(s, false);
> qemu_log("\n");
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
>
> @@ -4094,11 +4094,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
> #ifdef DEBUG_DISAS
> if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP_IND)
> && qemu_log_in_addr_range(tb->pc))) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("OP before indirect lowering:\n");
> tcg_dump_ops(s, false);
> qemu_log("\n");
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
> /* Replace indirect temps with direct temps. */
> @@ -4115,11 +4115,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
> #ifdef DEBUG_DISAS
> if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP_OPT)
> && qemu_log_in_addr_range(tb->pc))) {
> - qemu_log_lock();
> + FILE *logfile = qemu_log_lock();
> qemu_log("OP after optimization and liveness analysis:\n");
> tcg_dump_ops(s, true);
> qemu_log("\n");
> - qemu_log_unlock();
> + qemu_log_unlock(logfile);
> }
> #endif
--
Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 4/4] Added tests for close and change of logfile.
2019-11-07 14:26 ` [PATCH 4/4] Added tests for close and change of logfile Robert Foley
@ 2019-11-07 16:32 ` Alex Bennée
2019-11-07 17:26 ` Alex Bennée
2019-11-07 21:33 ` Robert Foley
0 siblings, 2 replies; 19+ messages in thread
From: Alex Bennée @ 2019-11-07 16:32 UTC (permalink / raw)
To: Robert Foley; +Cc: peter.puhov, qemu-devel
Robert Foley <robert.foley@linaro.org> writes:
> One test ensures that the logfile handle is still valid even if
> the logfile is changed during logging.
> The other test validates that the logfile handle remains valid under
> the logfile lock even if the logfile is closed.
>
> Signed-off-by: Robert Foley <robert.foley@linaro.org>
> ---
> tests/test-logging.c | 74 ++++++++++++++++++++++++++++++++++++++++++++
> 1 file changed, 74 insertions(+)
>
> diff --git a/tests/test-logging.c b/tests/test-logging.c
> index a12585f70a..a3190ff92c 100644
> --- a/tests/test-logging.c
> +++ b/tests/test-logging.c
> @@ -108,6 +108,76 @@ static void test_parse_path(gconstpointer data)
> error_free_or_abort(&err);
> }
>
> +static void test_logfile_write(gconstpointer data)
> +{
> + QemuLogFile *logfile;
> + gchar const *dir = data;
> + Error *err = NULL;
> + gchar *file_path;
> + gchar *file_path1;
with g_autofree char *file_path you can avoid the free down bellow.
> + FILE *orig_fd;
> +
> + file_path = g_build_filename(dir, "qemu_test_log_write0.log", NULL);
> + file_path1 = g_build_filename(dir, "qemu_test_log_write1.log", NULL);
> +
> + /*
> + * Test that even if an open file handle is changed,
> + * our handle remains valid due to RCU.
> + */
> + qemu_set_log_filename(file_path, &err);
> + g_assert(!err);
> + rcu_read_lock();
> + logfile = atomic_rcu_read(&qemu_logfile);
> + orig_fd = logfile->fd;
> + g_assert(logfile && logfile->fd);
> + fprintf(logfile->fd, "%s 1st write to file\n", __func__);
> + fflush(logfile->fd);
> +
> + /* Change the logfile and ensure that the handle is still valid. */
> + qemu_set_log_filename(file_path1, &err);
> + g_assert(!err);
Maybe better would be:
logfile2 = atomic_rcu_read(&qemu_logfile);
g_assert(logfile->fd == orig_fd);
g_assert(logfile2->fd != logfile->fd);
fprintf(logfile2->fd, "%s 2nd write to file\n", __func__);
fflush(logfile2->fd);
<snip>
> + g_assert(logfile->fd == orig_fd);
> + fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
> + fflush(logfile->fd);
> + rcu_read_unlock();
> +
> + g_free(file_path);
> + g_free(file_path1);
> +}
> +
> +static void test_logfile_lock(gconstpointer data)
> +{
> + FILE *logfile;
> + gchar const *dir = data;
> + Error *err = NULL;
> + gchar *file_path;
g_autofree
> +
> + file_path = g_build_filename(dir, "qemu_test_logfile_lock0.log", NULL);
> +
> + /*
> + * Test the use of the logfile lock, such
> + * that even if an open file handle is closed,
> + * our handle remains valid for use due to RCU.
> + */
> + qemu_set_log_filename(file_path, &err);
> + logfile = qemu_log_lock();
> + g_assert(logfile);
> + fprintf(logfile, "%s 1st write to file\n", __func__);
> + fflush(logfile);
> +
> + /*
> + * Initiate a close file and make sure our handle remains
> + * valid since we still have the logfile lock.
> + */
> + qemu_log_close();
> + fprintf(logfile, "%s 2nd write to file\n", __func__);
> + fflush(logfile);
> + qemu_log_unlock(logfile);
> +
> + g_assert(!err);
> + g_free(file_path);
> +}
> +
> /* Remove a directory and all its entries (non-recursive). */
> static void rmdir_full(gchar const *root)
> {
> @@ -134,6 +204,10 @@ int main(int argc, char **argv)
>
> g_test_add_func("/logging/parse_range", test_parse_range);
> g_test_add_data_func("/logging/parse_path", tmp_path, test_parse_path);
> + g_test_add_data_func("/logging/logfile_write_path",
> + tmp_path, test_logfile_write);
> + g_test_add_data_func("/logging/logfile_lock_path",
> + tmp_path, test_logfile_lock);
>
> rc = g_test_run();
--
Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 0/4] Make the qemu_logfile handle thread safe.
2019-11-07 14:26 [PATCH 0/4] Make the qemu_logfile handle thread safe Robert Foley
` (4 preceding siblings ...)
2019-11-07 14:46 ` [PATCH 0/4] Make the qemu_logfile handle thread safe no-reply
@ 2019-11-07 16:35 ` Alex Bennée
5 siblings, 0 replies; 19+ messages in thread
From: Alex Bennée @ 2019-11-07 16:35 UTC (permalink / raw)
To: Robert Foley; +Cc: peter.puhov, qemu-devel
Robert Foley <robert.foley@linaro.org> writes:
> This patch adds thread safety to the qemu_logfile handle. This now
> allows changing the logfile while logging is active, and also solves
> the issue of a seg fault while changing the logfile.
>
> This patch adds use of RCU for handling the swap out of the
> old qemu_logfile file descriptor.
I've finished my pass. Looks pretty good - a few minor comments around
the persistence of the read lock and some minor stylistic nits.
>
> Robert Foley (4):
> Add a mutex to guarantee single writer to qemu_logfile handle.
> Add use of RCU for qemu_logfile.
> qemu_log_lock/unlock now preserves the qemu_logfile handle.
> Added tests for close and change of logfile.
>
> accel/tcg/cpu-exec.c | 4 +-
> accel/tcg/translate-all.c | 4 +-
> accel/tcg/translator.c | 4 +-
> exec.c | 4 +-
> hw/net/can/can_sja1000.c | 4 +-
> include/exec/log.h | 33 ++++++++++--
> include/qemu/log.h | 51 +++++++++++++++---
> net/can/can_socketcan.c | 5 +-
> target/cris/translate.c | 4 +-
> target/i386/translate.c | 5 +-
> target/lm32/translate.c | 4 +-
> target/microblaze/translate.c | 4 +-
> target/nios2/translate.c | 4 +-
> target/tilegx/translate.c | 7 +--
> target/unicore32/translate.c | 4 +-
> tcg/tcg.c | 28 ++++++----
> tests/test-logging.c | 74 ++++++++++++++++++++++++++
> util/log.c | 99 ++++++++++++++++++++++++++++-------
> 18 files changed, 273 insertions(+), 69 deletions(-)
--
Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 1/4] Add a mutex to guarantee single writer to qemu_logfile handle.
2019-11-07 14:26 ` [PATCH 1/4] Add a mutex to guarantee single writer to qemu_logfile handle Robert Foley
@ 2019-11-07 16:53 ` Alex Bennée
2019-11-07 21:54 ` Robert Foley
0 siblings, 1 reply; 19+ messages in thread
From: Alex Bennée @ 2019-11-07 16:53 UTC (permalink / raw)
To: Robert Foley; +Cc: peter.puhov, qemu-devel
Robert Foley <robert.foley@linaro.org> writes:
> This is being added in preparation for using RCU with the logfile handle.
> Also added qemu_logfile_init() for initializing the logfile mutex.
>
> Signed-off-by: Robert Foley <robert.foley@linaro.org>
> ---
> util/log.c | 23 +++++++++++++++++++++++
> 1 file changed, 23 insertions(+)
>
> diff --git a/util/log.c b/util/log.c
> index 1ca13059ee..dff2f98c8c 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -24,8 +24,11 @@
> #include "qapi/error.h"
> #include "qemu/cutils.h"
> #include "trace/control.h"
> +#include "qemu/thread.h"
>
> static char *logfilename;
> +static bool qemu_logfile_initialized;
> +static QemuMutex qemu_logfile_mutex;
> FILE *qemu_logfile;
> int qemu_loglevel;
> static int log_append = 0;
> @@ -49,6 +52,14 @@ int qemu_log(const char *fmt, ...)
> return ret;
> }
>
> +static void qemu_logfile_init(void)
> +{
> + if (!qemu_logfile_initialized) {
> + qemu_mutex_init(&qemu_logfile_mutex);
> + qemu_logfile_initialized = true;
> + }
> +}
> +
> static bool log_uses_own_buffers;
>
> /* enable or disable low levels log */
> @@ -58,6 +69,12 @@ void qemu_set_log(int log_flags)
> #ifdef CONFIG_TRACE_LOG
> qemu_loglevel |= LOG_TRACE;
> #endif
> +
> + /* Is there a better place to call this to init the logfile subsystem? */
> + if (!qemu_logfile_initialized) {
> + qemu_logfile_init();
> + }
It wouldn't be the worst thing in the world to expose:
qemu_logfile_init()
and make vl.c and main.c call it before the setup. Then you can drop the
flag or even just g_assert(qemu_log_mutex_initialised) in qemu_set_log
and qemu_set_logfile.
In fact you could just use:
static void __attribute__((__constructor__)) qemu_logfile_init(void)
and make the compiler do it for you.
> + qemu_mutex_lock(&qemu_logfile_mutex);
> if (!qemu_logfile &&
> (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
> if (logfilename) {
> @@ -93,6 +110,7 @@ void qemu_set_log(int log_flags)
> log_append = 1;
> }
> }
> + qemu_mutex_unlock(&qemu_logfile_mutex);
> if (qemu_logfile &&
> (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
> qemu_log_close();
> @@ -114,6 +132,11 @@ void qemu_set_log_filename(const char *filename, Error **errp)
> char *pidstr;
> g_free(logfilename);
>
> + /* Is there a better place to call this to init the logfile subsystem? */
> + if (!qemu_logfile_initialized) {
> + qemu_logfile_init();
> + }
> +
> pidstr = strstr(filename, "%");
> if (pidstr) {
> /* We only accept one %d, no other format strings */
--
Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 4/4] Added tests for close and change of logfile.
2019-11-07 16:32 ` Alex Bennée
@ 2019-11-07 17:26 ` Alex Bennée
2019-11-07 19:38 ` Robert Foley
2019-11-07 21:33 ` Robert Foley
1 sibling, 1 reply; 19+ messages in thread
From: Alex Bennée @ 2019-11-07 17:26 UTC (permalink / raw)
To: Robert Foley; +Cc: peter.puhov, qemu-devel
Alex Bennée <alex.bennee@linaro.org> writes:
> Robert Foley <robert.foley@linaro.org> writes:
>
>> One test ensures that the logfile handle is still valid even if
>> the logfile is changed during logging.
>> The other test validates that the logfile handle remains valid under
>> the logfile lock even if the logfile is closed.
Also this doesn't see to work:
17:24:31 [alex@zen:~/l/q/b/all] review/rcu-logfile|… 2 + ./tests/test-logging
/logging/parse_range: OK
/logging/parse_path: OK
/logging/logfile_write_path: free(): double free detected in tcache 2
fish: “./tests/test-logging” terminated by signal SIGABRT (Abort)
in gdb
Starting program: /home/alex/lsrc/qemu.git/builds/all/tests/test-logging
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7ffff6f38700 (LWP 28960)]
/logging/parse_range: OK
/logging/parse_path: OK
/logging/logfile_write_path: free(): double free detected in tcache 2
Thread 1 "test-logging" received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x00007ffff7587535 in __GI_abort () at abort.c:79
#2 0x00007ffff75de508 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7ffff76e928d "%s\n") at ../sysdeps/posix/libc_fatal.c:181
#3 0x00007ffff75e4c1a in malloc_printerr (str=str@entry=0x7ffff76eaf58 "free(): double free detected in tcache 2") at malloc.c:5341
#4 0x00007ffff75e66fd in _int_free (av=0x7ffff7720c40 <main_arena>, p=0x5555555cac40, have_lock=<optimized out>) at malloc.c:4193
#5 0x00005555555614a8 in qemu_set_log_filename (filename=0x5555555cb110 "/tmp/qemu-test-logging.RO35A0/qemu_test_log_write0.log", errp=0x7fffffffdef0) at /home/alex/lsrc/qemu.git/util/log.c:148
#6 0x000055555555d8be in test_logfile_write (data=0x5555555c7370) at /home/alex/lsrc/qemu.git/tests/test-logging.c:127
#7 0x00007ffff7cdc15a in test_case_run (tc=0x5555555c9c60) at ../../../glib/gtestutils.c:2318
#8 g_test_run_suite_internal (suite=suite@entry=0x5555555c8a40, path=path@entry=0x0) at ../../../glib/gtestutils.c:2403
#9 0x00007ffff7cdc014 in g_test_run_suite_internal (suite=suite@entry=0x5555555c8a20, path=path@entry=0x0) at ../../../glib/gtestutils.c:2415
#10 0x00007ffff7cdc412 in g_test_run_suite (suite=0x5555555c8a20) at ../../../glib/gtestutils.c:2490
#11 0x00007ffff7cdc431 in g_test_run () at ../../../glib/gtestutils.c:1755
#12 0x000055555555ce07 in main (argc=<optimized out>, argv=<optimized out>) at /home/alex/lsrc/qemu.git/tests/test-logging.c:212
>>
>> Signed-off-by: Robert Foley <robert.foley@linaro.org>
>> ---
>> tests/test-logging.c | 74 ++++++++++++++++++++++++++++++++++++++++++++
>> 1 file changed, 74 insertions(+)
>>
>> diff --git a/tests/test-logging.c b/tests/test-logging.c
>> index a12585f70a..a3190ff92c 100644
>> --- a/tests/test-logging.c
>> +++ b/tests/test-logging.c
>> @@ -108,6 +108,76 @@ static void test_parse_path(gconstpointer data)
>> error_free_or_abort(&err);
>> }
>>
>> +static void test_logfile_write(gconstpointer data)
>> +{
>> + QemuLogFile *logfile;
>> + gchar const *dir = data;
>> + Error *err = NULL;
>> + gchar *file_path;
>> + gchar *file_path1;
>
> with g_autofree char *file_path you can avoid the free down bellow.
>
>> + FILE *orig_fd;
>> +
>> + file_path = g_build_filename(dir, "qemu_test_log_write0.log", NULL);
>> + file_path1 = g_build_filename(dir, "qemu_test_log_write1.log", NULL);
>> +
>> + /*
>> + * Test that even if an open file handle is changed,
>> + * our handle remains valid due to RCU.
>> + */
>> + qemu_set_log_filename(file_path, &err);
>> + g_assert(!err);
>> + rcu_read_lock();
>> + logfile = atomic_rcu_read(&qemu_logfile);
>> + orig_fd = logfile->fd;
>> + g_assert(logfile && logfile->fd);
>> + fprintf(logfile->fd, "%s 1st write to file\n", __func__);
>> + fflush(logfile->fd);
>> +
>> + /* Change the logfile and ensure that the handle is still valid. */
>> + qemu_set_log_filename(file_path1, &err);
>> + g_assert(!err);
>
> Maybe better would be:
>
> logfile2 = atomic_rcu_read(&qemu_logfile);
> g_assert(logfile->fd == orig_fd);
> g_assert(logfile2->fd != logfile->fd);
> fprintf(logfile2->fd, "%s 2nd write to file\n", __func__);
> fflush(logfile2->fd);
>
> <snip>
>> + g_assert(logfile->fd == orig_fd);
>> + fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
>> + fflush(logfile->fd);
>> + rcu_read_unlock();
>> +
>> + g_free(file_path);
>> + g_free(file_path1);
>> +}
>> +
>> +static void test_logfile_lock(gconstpointer data)
>> +{
>> + FILE *logfile;
>> + gchar const *dir = data;
>> + Error *err = NULL;
>> + gchar *file_path;
>
> g_autofree
>
>> +
>> + file_path = g_build_filename(dir, "qemu_test_logfile_lock0.log", NULL);
>> +
>> + /*
>> + * Test the use of the logfile lock, such
>> + * that even if an open file handle is closed,
>> + * our handle remains valid for use due to RCU.
>> + */
>> + qemu_set_log_filename(file_path, &err);
>> + logfile = qemu_log_lock();
>> + g_assert(logfile);
>> + fprintf(logfile, "%s 1st write to file\n", __func__);
>> + fflush(logfile);
>> +
>> + /*
>> + * Initiate a close file and make sure our handle remains
>> + * valid since we still have the logfile lock.
>> + */
>> + qemu_log_close();
>> + fprintf(logfile, "%s 2nd write to file\n", __func__);
>> + fflush(logfile);
>> + qemu_log_unlock(logfile);
>> +
>> + g_assert(!err);
>> + g_free(file_path);
>> +}
>> +
>> /* Remove a directory and all its entries (non-recursive). */
>> static void rmdir_full(gchar const *root)
>> {
>> @@ -134,6 +204,10 @@ int main(int argc, char **argv)
>>
>> g_test_add_func("/logging/parse_range", test_parse_range);
>> g_test_add_data_func("/logging/parse_path", tmp_path, test_parse_path);
>> + g_test_add_data_func("/logging/logfile_write_path",
>> + tmp_path, test_logfile_write);
>> + g_test_add_data_func("/logging/logfile_lock_path",
>> + tmp_path, test_logfile_lock);
>>
>> rc = g_test_run();
--
Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 4/4] Added tests for close and change of logfile.
2019-11-07 17:26 ` Alex Bennée
@ 2019-11-07 19:38 ` Robert Foley
2019-11-07 20:12 ` Alex Bennée
0 siblings, 1 reply; 19+ messages in thread
From: Robert Foley @ 2019-11-07 19:38 UTC (permalink / raw)
To: Alex Bennée; +Cc: Peter Puhov, qemu-devel
Thanks for providing the stack trace.
We debugged this and it seems to come about because of an interesting
circumstance. We added our new tests after a pre-existing test,
parse_path(), which runs into an issue, a dangling pointer, which
could lead to a double free. There were no other tests after the test
that ran into the issue, so the double free was not exposed until we
added our test which called qemu_set_log_filename().
Upon entry to qemu_set_log_filename() it frees logfilename. In the
case where we get an error, we return out without setting the
logfilename to NULL.
And on next call into this function we will end up with a double free.
For a fix, we could put this at the beginning of qemu_set_log_filename().
if (logfilename) {
g_free(logfilename);
logfilename = NULL;
}
We were curious to understand why we did not see it in our own
testing. Although we did run make check before our first post, we did
not see this issue. The docker tests seem to use something like
MALLOC_CHECK_, which catches memory issues like this. We will be
sure to run the docker tests as well in the future.
On Thu, 7 Nov 2019 at 12:26, Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> Alex Bennée <alex.bennee@linaro.org> writes:
>
> > Robert Foley <robert.foley@linaro.org> writes:
> >
> >> One test ensures that the logfile handle is still valid even if
> >> the logfile is changed during logging.
> >> The other test validates that the logfile handle remains valid under
> >> the logfile lock even if the logfile is closed.
>
> Also this doesn't see to work:
>
> 17:24:31 [alex@zen:~/l/q/b/all] review/rcu-logfile|… 2 + ./tests/test-logging
> /logging/parse_range: OK
> /logging/parse_path: OK
> /logging/logfile_write_path: free(): double free detected in tcache 2
> fish: “./tests/test-logging” terminated by signal SIGABRT (Abort)
>
> in gdb
>
> Starting program: /home/alex/lsrc/qemu.git/builds/all/tests/test-logging
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
> [New Thread 0x7ffff6f38700 (LWP 28960)]
> /logging/parse_range: OK
> /logging/parse_path: OK
> /logging/logfile_write_path: free(): double free detected in tcache 2
>
> Thread 1 "test-logging" received signal SIGABRT, Aborted.
> __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
> (gdb) bt
> #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> #1 0x00007ffff7587535 in __GI_abort () at abort.c:79
> #2 0x00007ffff75de508 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7ffff76e928d "%s\n") at ../sysdeps/posix/libc_fatal.c:181
> #3 0x00007ffff75e4c1a in malloc_printerr (str=str@entry=0x7ffff76eaf58 "free(): double free detected in tcache 2") at malloc.c:5341
> #4 0x00007ffff75e66fd in _int_free (av=0x7ffff7720c40 <main_arena>, p=0x5555555cac40, have_lock=<optimized out>) at malloc.c:4193
> #5 0x00005555555614a8 in qemu_set_log_filename (filename=0x5555555cb110 "/tmp/qemu-test-logging.RO35A0/qemu_test_log_write0.log", errp=0x7fffffffdef0) at /home/alex/lsrc/qemu.git/util/log.c:148
> #6 0x000055555555d8be in test_logfile_write (data=0x5555555c7370) at /home/alex/lsrc/qemu.git/tests/test-logging.c:127
> #7 0x00007ffff7cdc15a in test_case_run (tc=0x5555555c9c60) at ../../../glib/gtestutils.c:2318
> #8 g_test_run_suite_internal (suite=suite@entry=0x5555555c8a40, path=path@entry=0x0) at ../../../glib/gtestutils.c:2403
> #9 0x00007ffff7cdc014 in g_test_run_suite_internal (suite=suite@entry=0x5555555c8a20, path=path@entry=0x0) at ../../../glib/gtestutils.c:2415
> #10 0x00007ffff7cdc412 in g_test_run_suite (suite=0x5555555c8a20) at ../../../glib/gtestutils.c:2490
> #11 0x00007ffff7cdc431 in g_test_run () at ../../../glib/gtestutils.c:1755
> #12 0x000055555555ce07 in main (argc=<optimized out>, argv=<optimized out>) at /home/alex/lsrc/qemu.git/tests/test-logging.c:212
>
>
> >>
> >> Signed-off-by: Robert Foley <robert.foley@linaro.org>
> >> ---
> >> tests/test-logging.c | 74 ++++++++++++++++++++++++++++++++++++++++++++
> >> 1 file changed, 74 insertions(+)
> >>
> >> diff --git a/tests/test-logging.c b/tests/test-logging.c
> >> index a12585f70a..a3190ff92c 100644
> >> --- a/tests/test-logging.c
> >> +++ b/tests/test-logging.c
> >> @@ -108,6 +108,76 @@ static void test_parse_path(gconstpointer data)
> >> error_free_or_abort(&err);
> >> }
> >>
> >> +static void test_logfile_write(gconstpointer data)
> >> +{
> >> + QemuLogFile *logfile;
> >> + gchar const *dir = data;
> >> + Error *err = NULL;
> >> + gchar *file_path;
> >> + gchar *file_path1;
> >
> > with g_autofree char *file_path you can avoid the free down bellow.
> >
> >> + FILE *orig_fd;
> >> +
> >> + file_path = g_build_filename(dir, "qemu_test_log_write0.log", NULL);
> >> + file_path1 = g_build_filename(dir, "qemu_test_log_write1.log", NULL);
> >> +
> >> + /*
> >> + * Test that even if an open file handle is changed,
> >> + * our handle remains valid due to RCU.
> >> + */
> >> + qemu_set_log_filename(file_path, &err);
> >> + g_assert(!err);
> >> + rcu_read_lock();
> >> + logfile = atomic_rcu_read(&qemu_logfile);
> >> + orig_fd = logfile->fd;
> >> + g_assert(logfile && logfile->fd);
> >> + fprintf(logfile->fd, "%s 1st write to file\n", __func__);
> >> + fflush(logfile->fd);
> >> +
> >> + /* Change the logfile and ensure that the handle is still valid. */
> >> + qemu_set_log_filename(file_path1, &err);
> >> + g_assert(!err);
> >
> > Maybe better would be:
> >
> > logfile2 = atomic_rcu_read(&qemu_logfile);
> > g_assert(logfile->fd == orig_fd);
> > g_assert(logfile2->fd != logfile->fd);
> > fprintf(logfile2->fd, "%s 2nd write to file\n", __func__);
> > fflush(logfile2->fd);
> >
> > <snip>
> >> + g_assert(logfile->fd == orig_fd);
> >> + fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
> >> + fflush(logfile->fd);
> >> + rcu_read_unlock();
> >> +
> >> + g_free(file_path);
> >> + g_free(file_path1);
> >> +}
> >> +
> >> +static void test_logfile_lock(gconstpointer data)
> >> +{
> >> + FILE *logfile;
> >> + gchar const *dir = data;
> >> + Error *err = NULL;
> >> + gchar *file_path;
> >
> > g_autofree
> >
> >> +
> >> + file_path = g_build_filename(dir, "qemu_test_logfile_lock0.log", NULL);
> >> +
> >> + /*
> >> + * Test the use of the logfile lock, such
> >> + * that even if an open file handle is closed,
> >> + * our handle remains valid for use due to RCU.
> >> + */
> >> + qemu_set_log_filename(file_path, &err);
> >> + logfile = qemu_log_lock();
> >> + g_assert(logfile);
> >> + fprintf(logfile, "%s 1st write to file\n", __func__);
> >> + fflush(logfile);
> >> +
> >> + /*
> >> + * Initiate a close file and make sure our handle remains
> >> + * valid since we still have the logfile lock.
> >> + */
> >> + qemu_log_close();
> >> + fprintf(logfile, "%s 2nd write to file\n", __func__);
> >> + fflush(logfile);
> >> + qemu_log_unlock(logfile);
> >> +
> >> + g_assert(!err);
> >> + g_free(file_path);
> >> +}
> >> +
> >> /* Remove a directory and all its entries (non-recursive). */
> >> static void rmdir_full(gchar const *root)
> >> {
> >> @@ -134,6 +204,10 @@ int main(int argc, char **argv)
> >>
> >> g_test_add_func("/logging/parse_range", test_parse_range);
> >> g_test_add_data_func("/logging/parse_path", tmp_path, test_parse_path);
> >> + g_test_add_data_func("/logging/logfile_write_path",
> >> + tmp_path, test_logfile_write);
> >> + g_test_add_data_func("/logging/logfile_lock_path",
> >> + tmp_path, test_logfile_lock);
> >>
> >> rc = g_test_run();
>
>
> --
> Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 4/4] Added tests for close and change of logfile.
2019-11-07 19:38 ` Robert Foley
@ 2019-11-07 20:12 ` Alex Bennée
2019-11-07 22:11 ` Robert Foley
0 siblings, 1 reply; 19+ messages in thread
From: Alex Bennée @ 2019-11-07 20:12 UTC (permalink / raw)
To: Robert Foley; +Cc: Peter Puhov, qemu-devel
Robert Foley <robert.foley@linaro.org> writes:
> Thanks for providing the stack trace.
>
> We debugged this and it seems to come about because of an interesting
> circumstance. We added our new tests after a pre-existing test,
> parse_path(), which runs into an issue, a dangling pointer, which
> could lead to a double free. There were no other tests after the test
> that ran into the issue, so the double free was not exposed until we
> added our test which called qemu_set_log_filename().
>
> Upon entry to qemu_set_log_filename() it frees logfilename. In the
> case where we get an error, we return out without setting the
> logfilename to NULL.
> And on next call into this function we will end up with a double free.
>
> For a fix, we could put this at the beginning of qemu_set_log_filename().
> if (logfilename) {
> g_free(logfilename);
> logfilename = NULL;
> }
g_free(logfilename) should be safe against NULL. However we need to
ensure that logfilename is NULL'ed after it so we don't see the double
free.
> We were curious to understand why we did not see it in our own
> testing. Although we did run make check before our first post, we did
> not see this issue. The docker tests seem to use something like
> MALLOC_CHECK_, which catches memory issues like this. We will be
> sure to run the docker tests as well in the future.
I was just running in my normal checkout - it could depend on how glibc
was built for your system though. Mine is Debian Buster.
>
> On Thu, 7 Nov 2019 at 12:26, Alex Bennée <alex.bennee@linaro.org> wrote:
>>
>>
>> Alex Bennée <alex.bennee@linaro.org> writes:
>>
>> > Robert Foley <robert.foley@linaro.org> writes:
>> >
>> >> One test ensures that the logfile handle is still valid even if
>> >> the logfile is changed during logging.
>> >> The other test validates that the logfile handle remains valid under
>> >> the logfile lock even if the logfile is closed.
>>
>> Also this doesn't see to work:
>>
>> 17:24:31 [alex@zen:~/l/q/b/all] review/rcu-logfile|… 2 + ./tests/test-logging
>> /logging/parse_range: OK
>> /logging/parse_path: OK
>> /logging/logfile_write_path: free(): double free detected in tcache 2
>> fish: “./tests/test-logging” terminated by signal SIGABRT (Abort)
>>
>> in gdb
>>
>> Starting program: /home/alex/lsrc/qemu.git/builds/all/tests/test-logging
>> [Thread debugging using libthread_db enabled]
>> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
>> [New Thread 0x7ffff6f38700 (LWP 28960)]
>> /logging/parse_range: OK
>> /logging/parse_path: OK
>> /logging/logfile_write_path: free(): double free detected in tcache 2
>>
>> Thread 1 "test-logging" received signal SIGABRT, Aborted.
>> __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
>> 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
>> (gdb) bt
>> #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
>> #1 0x00007ffff7587535 in __GI_abort () at abort.c:79
>> #2 0x00007ffff75de508 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7ffff76e928d "%s\n") at ../sysdeps/posix/libc_fatal.c:181
>> #3 0x00007ffff75e4c1a in malloc_printerr (str=str@entry=0x7ffff76eaf58 "free(): double free detected in tcache 2") at malloc.c:5341
>> #4 0x00007ffff75e66fd in _int_free (av=0x7ffff7720c40 <main_arena>, p=0x5555555cac40, have_lock=<optimized out>) at malloc.c:4193
>> #5 0x00005555555614a8 in qemu_set_log_filename (filename=0x5555555cb110 "/tmp/qemu-test-logging.RO35A0/qemu_test_log_write0.log", errp=0x7fffffffdef0) at /home/alex/lsrc/qemu.git/util/log.c:148
>> #6 0x000055555555d8be in test_logfile_write (data=0x5555555c7370) at /home/alex/lsrc/qemu.git/tests/test-logging.c:127
>> #7 0x00007ffff7cdc15a in test_case_run (tc=0x5555555c9c60) at ../../../glib/gtestutils.c:2318
>> #8 g_test_run_suite_internal (suite=suite@entry=0x5555555c8a40, path=path@entry=0x0) at ../../../glib/gtestutils.c:2403
>> #9 0x00007ffff7cdc014 in g_test_run_suite_internal (suite=suite@entry=0x5555555c8a20, path=path@entry=0x0) at ../../../glib/gtestutils.c:2415
>> #10 0x00007ffff7cdc412 in g_test_run_suite (suite=0x5555555c8a20) at ../../../glib/gtestutils.c:2490
>> #11 0x00007ffff7cdc431 in g_test_run () at ../../../glib/gtestutils.c:1755
>> #12 0x000055555555ce07 in main (argc=<optimized out>, argv=<optimized out>) at /home/alex/lsrc/qemu.git/tests/test-logging.c:212
>>
>>
>> >>
>> >> Signed-off-by: Robert Foley <robert.foley@linaro.org>
>> >> ---
>> >> tests/test-logging.c | 74 ++++++++++++++++++++++++++++++++++++++++++++
>> >> 1 file changed, 74 insertions(+)
>> >>
>> >> diff --git a/tests/test-logging.c b/tests/test-logging.c
>> >> index a12585f70a..a3190ff92c 100644
>> >> --- a/tests/test-logging.c
>> >> +++ b/tests/test-logging.c
>> >> @@ -108,6 +108,76 @@ static void test_parse_path(gconstpointer data)
>> >> error_free_or_abort(&err);
>> >> }
>> >>
>> >> +static void test_logfile_write(gconstpointer data)
>> >> +{
>> >> + QemuLogFile *logfile;
>> >> + gchar const *dir = data;
>> >> + Error *err = NULL;
>> >> + gchar *file_path;
>> >> + gchar *file_path1;
>> >
>> > with g_autofree char *file_path you can avoid the free down bellow.
>> >
>> >> + FILE *orig_fd;
>> >> +
>> >> + file_path = g_build_filename(dir, "qemu_test_log_write0.log", NULL);
>> >> + file_path1 = g_build_filename(dir, "qemu_test_log_write1.log", NULL);
>> >> +
>> >> + /*
>> >> + * Test that even if an open file handle is changed,
>> >> + * our handle remains valid due to RCU.
>> >> + */
>> >> + qemu_set_log_filename(file_path, &err);
>> >> + g_assert(!err);
>> >> + rcu_read_lock();
>> >> + logfile = atomic_rcu_read(&qemu_logfile);
>> >> + orig_fd = logfile->fd;
>> >> + g_assert(logfile && logfile->fd);
>> >> + fprintf(logfile->fd, "%s 1st write to file\n", __func__);
>> >> + fflush(logfile->fd);
>> >> +
>> >> + /* Change the logfile and ensure that the handle is still valid. */
>> >> + qemu_set_log_filename(file_path1, &err);
>> >> + g_assert(!err);
>> >
>> > Maybe better would be:
>> >
>> > logfile2 = atomic_rcu_read(&qemu_logfile);
>> > g_assert(logfile->fd == orig_fd);
>> > g_assert(logfile2->fd != logfile->fd);
>> > fprintf(logfile2->fd, "%s 2nd write to file\n", __func__);
>> > fflush(logfile2->fd);
>> >
>> > <snip>
>> >> + g_assert(logfile->fd == orig_fd);
>> >> + fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
>> >> + fflush(logfile->fd);
>> >> + rcu_read_unlock();
>> >> +
>> >> + g_free(file_path);
>> >> + g_free(file_path1);
>> >> +}
>> >> +
>> >> +static void test_logfile_lock(gconstpointer data)
>> >> +{
>> >> + FILE *logfile;
>> >> + gchar const *dir = data;
>> >> + Error *err = NULL;
>> >> + gchar *file_path;
>> >
>> > g_autofree
>> >
>> >> +
>> >> + file_path = g_build_filename(dir, "qemu_test_logfile_lock0.log", NULL);
>> >> +
>> >> + /*
>> >> + * Test the use of the logfile lock, such
>> >> + * that even if an open file handle is closed,
>> >> + * our handle remains valid for use due to RCU.
>> >> + */
>> >> + qemu_set_log_filename(file_path, &err);
>> >> + logfile = qemu_log_lock();
>> >> + g_assert(logfile);
>> >> + fprintf(logfile, "%s 1st write to file\n", __func__);
>> >> + fflush(logfile);
>> >> +
>> >> + /*
>> >> + * Initiate a close file and make sure our handle remains
>> >> + * valid since we still have the logfile lock.
>> >> + */
>> >> + qemu_log_close();
>> >> + fprintf(logfile, "%s 2nd write to file\n", __func__);
>> >> + fflush(logfile);
>> >> + qemu_log_unlock(logfile);
>> >> +
>> >> + g_assert(!err);
>> >> + g_free(file_path);
>> >> +}
>> >> +
>> >> /* Remove a directory and all its entries (non-recursive). */
>> >> static void rmdir_full(gchar const *root)
>> >> {
>> >> @@ -134,6 +204,10 @@ int main(int argc, char **argv)
>> >>
>> >> g_test_add_func("/logging/parse_range", test_parse_range);
>> >> g_test_add_data_func("/logging/parse_path", tmp_path, test_parse_path);
>> >> + g_test_add_data_func("/logging/logfile_write_path",
>> >> + tmp_path, test_logfile_write);
>> >> + g_test_add_data_func("/logging/logfile_lock_path",
>> >> + tmp_path, test_logfile_lock);
>> >>
>> >> rc = g_test_run();
>>
>>
>> --
>> Alex Bennée
--
Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 2/4] Add use of RCU for qemu_logfile.
2019-11-07 16:23 ` Alex Bennée
@ 2019-11-07 21:13 ` Robert Foley
0 siblings, 0 replies; 19+ messages in thread
From: Robert Foley @ 2019-11-07 21:13 UTC (permalink / raw)
To: Alex Bennée; +Cc: Peter Puhov, qemu-devel
On Thu, 7 Nov 2019 at 11:24, Alex Bennée <alex.bennee@linaro.org> wrote:
>
> Robert Foley <robert.foley@linaro.org> writes:
<snip>
> > diff --git a/include/qemu/log.h b/include/qemu/log.h
> > index a91105b2ad..975de18e23 100644
> > --- a/include/qemu/log.h
> > +++ b/include/qemu/log.h
> > @@ -3,9 +3,17 @@
> >
> > /* A small part of this API is split into its own header */
> > #include "qemu/log-for-trace.h"
> > +#include "qemu/rcu.h"
> > +
> > +struct QemuLogFile {
> > + struct rcu_head rcu;
> > + FILE *fd;
> > +};
> > +typedef struct QemuLogFile QemuLogFile;
>
> If you are declaring a typedef then do it in one:
>
> typedef struct QemuLogFile { ...
>
> We only really use the second form for opaque structs where the handle
> is passed around but the contents hidden from the rest of QEMU.
>
OK, makes sense. Will correct it. Thanks for explaining.
> >
> > /* Private global variable, don't use */
> > -extern FILE *qemu_logfile;
> > +extern QemuLogFile *qemu_logfile;
> > +
>
> Do we need multiple
Not 100% sure on the meaning here. Are you asking if we need to
extern this? We have a few other cases outside of the log module
where this is getting used so the extern is needed here.
> >
> > /*
> > * The new API:
> > @@ -25,7 +33,17 @@ static inline bool qemu_log_enabled(void)
> > */
> > static inline bool qemu_log_separate(void)
> > {
> > - return qemu_logfile != NULL && qemu_logfile != stderr;
> > + QemuLogFile *logfile;
> > +
> > + if (qemu_log_enabled()) {
> > + rcu_read_lock();
> > + logfile = atomic_rcu_read(&qemu_logfile);
> > + if (logfile && logfile->fd != stderr) {
> > + return true;
> > + }
> > + rcu_read_unlock();
> > + }
> > + return false;
>
> This is unbalanced as you'll have incremented the reader count. Also
> qemu_log_enabled() is also synonymous with logfile existing so you could
> fold that into:
>
> bool res = false;
>
> rcu_read_lock();
> *logfile = atomic_rcu_read(&qemu_logfile);
> if (logfile && logfile->fd != stderr) {
> res = true;
> }
> rcu_read_unlock();
> return res;
>
> There is technically a race there as the answer may become invalid after
> qemu_log_separate() returns. However given the users I don't see what
> could fail afterwards.
>
I agree, will make these changes.
> > }
> >
> > #define CPU_LOG_TB_OUT_ASM (1 << 0)
> > @@ -55,12 +73,23 @@ static inline bool qemu_log_separate(void)
> >
> > static inline void qemu_log_lock(void)
> > {
> > - qemu_flockfile(qemu_logfile);
> > + QemuLogFile *logfile;
> > + rcu_read_lock();
> > + logfile = atomic_rcu_read(&qemu_logfile);
> > + if (logfile) {
> > + qemu_flockfile(logfile->fd);
> > + }
> > + rcu_read_unlock();
> > }
>
> static inline FILE *fd qemu_log_lock(void)
> {
QemuLogFile *logfile;
> rcu_read_lock();
logfile = atomic_rcu_read(&qemu_logfile);
if (logfile) {
> qemu_flockfile(logfile->fd);
return logfile->fd;
> } else {
> rcu_read_unlock();
> return NULL;
> }
> }
>
> static inline qemu_log_unlock(FILE *fd)
> {
> if (fd) {
> qemu_funlockfile(fd);
> rcu_read_unlock();
> }
> }
>
> While the rcu_read_lock() is in progress then we won't ever finish with
> the fd - which we don't want to do until the file locking is finished.
Agree with the adjustments you made to qemu_log_lock(). I updated the
code above with a few tweaks for the QemuLogFile type returned by
atomic_rcu_read(). Does this look OK or is there any other adjustment
we should make here?
The intent here was for qemu_log_lock() to hold the rcu_read_lock()
until after we can qemu_funlockfile(fd). The idea being that we want
to prevent the fclose(fd) from happening by holding the
rcu_read_lock() across the qemu_log_lock() until qemu_log_unlock().
So we have the qemu_funlockfile(fd) first, and then once we're done
with the fd, it is safe to rcu_read_unlock().
> <snip>
<snip more>
> > diff --git a/util/log.c b/util/log.c
<snip>
> > @@ -65,6 +70,8 @@ static bool log_uses_own_buffers;
> > /* enable or disable low levels log */
> > void qemu_set_log(int log_flags)
> > {
> > + QemuLogFile *logfile;
> > +
> > qemu_loglevel = log_flags;
> > #ifdef CONFIG_TRACE_LOG
> > qemu_loglevel |= LOG_TRACE;
> > @@ -77,43 +84,51 @@ void qemu_set_log(int log_flags)
> > qemu_mutex_lock(&qemu_logfile_mutex);
> > if (!qemu_logfile &&
> > (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
> > + logfile = g_new0(QemuLogFile, 1);
> > if (logfilename) {
>
> You can assume logfilename exists as glib memory allocations would
> abort() otherwise.
This is good to know about the glib memory allocations as it relates
to the logfile above, since we did not add any check for null on
allocation.
We are thinking that logfilename might be NULL if we either never set
it with a call to qemu_set_log_filename(), or (with our intended new
fix) if we took an error actually opening the file in
qemu_set_log_filename(), and went down the error path.
> > - qemu_logfile = fopen(logfilename, log_append ? "a" : "w");
> > - if (!qemu_logfile) {
> > + logfile->fd = fopen(logfilename, log_append ? "a" : "w");
> > + if (!logfile->fd) {
> > + g_free(logfile);
> > perror(logfilename);
> > _exit(1);
<snip>
> > +void qemu_logfile_free(QemuLogFile *logfile)
>
> This can be static as it's internal to log.c
Absolutely, makes sense. Will change it.
> > +{
> > + if (logfile) {
>
> g_assert(logfile) instead of the if?
I agree, the assert is cleaner. Will change it.
> > + if (logfile->fd != stderr) {
> > + fclose(logfile->fd);
> > + }
> > + g_free(logfile);
> > + }
> > }
> >
> > /* Close the log file */
> > void qemu_log_close(void)
> > {
> > - if (qemu_logfile) {
> > - if (qemu_logfile != stderr) {
> > - fclose(qemu_logfile);
> > - }
> > - qemu_logfile = NULL;
> > + QemuLogFile *logfile;
> > +
> > + qemu_mutex_lock(&qemu_logfile_mutex);
> > + logfile = qemu_logfile;
> > +
> > + if (logfile) {
> > + atomic_rcu_set(&qemu_logfile, NULL);
> > + qemu_mutex_unlock(&qemu_logfile_mutex);
>
> I think you can move the both the unlocks out of the if/else and drop
> the else.
Agreed. Originally we were thinking to hold the lock until after the
call_rcu, but I agree with you, it seems safe to move it.
> > + call_rcu(logfile, qemu_logfile_free, rcu);
> > + } else {
> > + qemu_mutex_unlock(&qemu_logfile_mutex);
> > }
> > }
<snip>
> > diff --git a/tcg/tcg.c b/tcg/tcg.c
> > index 5475d49ed1..220eaac7c7 100644
> > --- a/tcg/tcg.c
> > +++ b/tcg/tcg.c
> > @@ -2114,9 +2114,17 @@ static void tcg_dump_ops(TCGContext *s, bool have_prefs)
> > }
> >
> > if (have_prefs || op->life) {
> > - for (; col < 40; ++col) {
> > - putc(' ', qemu_logfile);
> > +
> > + QemuLogFile *logfile;
> > +
> > + rcu_read_lock();
> > + logfile = atomic_rcu_read(&qemu_logfile);
>
> This can probably be a qemu_log_lock() instead given interleaving output
> is going to be confusing.
The function calling tcg_dump_ops(), tcg_gen_code(), already has the
qemu_log_lock() held.
We were thinking about another type of cleanup, but it applies to this
case as well, since this case is using the qemu_logfile. We were
thinking that at some point (another patch) it might be good to
cleanup the use of the qemu_logfile global so that it is only
referenced from inside the log module. We noticed a comment in
log.h calling it a private global, which we thought might imply that
it was an intent to keep it private, and that this cleanup might be a
good direction to move in.
Thanks,
-Rob Foley
> > + if (logfile) {
> > + for (; col < 40; ++col) {
> > + putc(' ', logfile->fd);
> > + }
> > }
> > + rcu_read_unlock();
>
> and qemu_log_unlock();
>
> This cleanup could even be in a separate patch.
>
> > }
> >
> > if (op->life) {
>
>
> --
> Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 3/4] qemu_log_lock/unlock now preserves the qemu_logfile handle.
2019-11-07 16:25 ` Alex Bennée
@ 2019-11-07 21:22 ` Robert Foley
0 siblings, 0 replies; 19+ messages in thread
From: Robert Foley @ 2019-11-07 21:22 UTC (permalink / raw)
To: Alex Bennée; +Cc: Peter Puhov, qemu-devel
On Thu, 7 Nov 2019 at 11:25, Alex Bennée <alex.bennee@linaro.org> wrote:
>
> Ahh there it is!
>
> We probably want to put the API change through before we add the RCU
> support - so swap the patch order around.
>
Absolutely, we will swap around the order of the patch.
-Rob Foley
On Thu, 7 Nov 2019 at 11:25, Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> Robert Foley <robert.foley@linaro.org> writes:
>
> > qemu_log_lock() now returns a handle and qemu_log_unlock() receives a
> > handle to unlock. This allows for changing the handle during logging
> > and ensures the lock() and unlock() are for the same file.
>
> Ahh there it is!
>
> We probably want to put the API change through before we add the RCU
> support - so swap the patch order around.
>
> >
> > Signed-off-by: Robert Foley <robert.foley@linaro.org>
> > ---
> > include/qemu/log.h | 14 +++++++-------
> > accel/tcg/cpu-exec.c | 4 ++--
> > accel/tcg/translate-all.c | 4 ++--
> > accel/tcg/translator.c | 4 ++--
> > exec.c | 4 ++--
> > hw/net/can/can_sja1000.c | 4 ++--
> > net/can/can_socketcan.c | 5 ++---
> > target/cris/translate.c | 4 ++--
> > target/i386/translate.c | 5 +++--
> > target/lm32/translate.c | 4 ++--
> > target/microblaze/translate.c | 4 ++--
> > target/nios2/translate.c | 4 ++--
> > target/tilegx/translate.c | 7 ++++---
> > target/unicore32/translate.c | 4 ++--
> > tcg/tcg.c | 16 ++++++++--------
> > 15 files changed, 44 insertions(+), 43 deletions(-)
> >
> > diff --git a/include/qemu/log.h b/include/qemu/log.h
> > index 975de18e23..3d0f47a479 100644
> > --- a/include/qemu/log.h
> > +++ b/include/qemu/log.h
> > @@ -71,25 +71,25 @@ static inline bool qemu_log_separate(void)
> > * qemu_loglevel is never set when qemu_logfile is unset.
> > */
> >
> > -static inline void qemu_log_lock(void)
> > +static inline FILE *qemu_log_lock(void)
> > {
> > QemuLogFile *logfile;
> > rcu_read_lock();
> > logfile = atomic_rcu_read(&qemu_logfile);
> > if (logfile) {
> > qemu_flockfile(logfile->fd);
> > + return logfile->fd;
> > }
> > rcu_read_unlock();
> > + return NULL;
> > }
> >
> > -static inline void qemu_log_unlock(void)
> > +static inline void qemu_log_unlock(FILE *fd)
> > {
> > - QemuLogFile *logfile;
> > - logfile = atomic_rcu_read(&qemu_logfile);
> > - if (logfile) {
> > - qemu_funlockfile(logfile->fd);
> > + if (fd) {
> > + qemu_funlockfile(fd);
> > + rcu_read_unlock();
> > }
> > - rcu_read_unlock();
> > }
> >
> > /* Logging functions: */
> > diff --git a/accel/tcg/cpu-exec.c b/accel/tcg/cpu-exec.c
> > index c01f59c743..62068d10c3 100644
> > --- a/accel/tcg/cpu-exec.c
> > +++ b/accel/tcg/cpu-exec.c
> > @@ -156,7 +156,7 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
> > #if defined(DEBUG_DISAS)
> > if (qemu_loglevel_mask(CPU_LOG_TB_CPU)
> > && qemu_log_in_addr_range(itb->pc)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > int flags = 0;
> > if (qemu_loglevel_mask(CPU_LOG_TB_FPU)) {
> > flags |= CPU_DUMP_FPU;
> > @@ -165,7 +165,7 @@ static inline tcg_target_ulong cpu_tb_exec(CPUState *cpu, TranslationBlock *itb)
> > flags |= CPU_DUMP_CCOP;
> > #endif
> > log_cpu_state(cpu, flags);
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif /* DEBUG_DISAS */
> >
> > diff --git a/accel/tcg/translate-all.c b/accel/tcg/translate-all.c
> > index 9f48da9472..bb325a2bc4 100644
> > --- a/accel/tcg/translate-all.c
> > +++ b/accel/tcg/translate-all.c
> > @@ -1804,7 +1804,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
> > #ifdef DEBUG_DISAS
> > if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM) &&
> > qemu_log_in_addr_range(tb->pc)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("OUT: [size=%d]\n", gen_code_size);
> > if (tcg_ctx->data_gen_ptr) {
> > size_t code_size = tcg_ctx->data_gen_ptr - tb->tc.ptr;
> > @@ -1829,7 +1829,7 @@ TranslationBlock *tb_gen_code(CPUState *cpu,
> > }
> > qemu_log("\n");
> > qemu_log_flush();
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> >
> > diff --git a/accel/tcg/translator.c b/accel/tcg/translator.c
> > index f977682be7..603d17ff83 100644
> > --- a/accel/tcg/translator.c
> > +++ b/accel/tcg/translator.c
> > @@ -138,11 +138,11 @@ void translator_loop(const TranslatorOps *ops, DisasContextBase *db,
> > #ifdef DEBUG_DISAS
> > if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> > && qemu_log_in_addr_range(db->pc_first)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("----------------\n");
> > ops->disas_log(db, cpu);
> > qemu_log("\n");
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> > }
> > diff --git a/exec.c b/exec.c
> > index ffdb518535..c994a00f10 100644
> > --- a/exec.c
> > +++ b/exec.c
> > @@ -1223,13 +1223,13 @@ void cpu_abort(CPUState *cpu, const char *fmt, ...)
> > fprintf(stderr, "\n");
> > cpu_dump_state(cpu, stderr, CPU_DUMP_FPU | CPU_DUMP_CCOP);
> > if (qemu_log_separate()) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("qemu: fatal: ");
> > qemu_log_vprintf(fmt, ap2);
> > qemu_log("\n");
> > log_cpu_state(cpu, CPU_DUMP_FPU | CPU_DUMP_CCOP);
> > qemu_log_flush();
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > qemu_log_close();
> > }
> > va_end(ap2);
> > diff --git a/hw/net/can/can_sja1000.c b/hw/net/can/can_sja1000.c
> > index 1f81341554..39c78faf9b 100644
> > --- a/hw/net/can/can_sja1000.c
> > +++ b/hw/net/can/can_sja1000.c
> > @@ -247,8 +247,8 @@ int can_sja_accept_filter(CanSJA1000State *s,
> > static void can_display_msg(const char *prefix, const qemu_can_frame *msg)
> > {
> > int i;
> > + FILE *logfile = qemu_log_lock();
> >
> > - qemu_log_lock();
> > qemu_log("%s%03X [%01d] %s %s",
> > prefix,
> > msg->can_id & QEMU_CAN_EFF_MASK,
> > @@ -261,7 +261,7 @@ static void can_display_msg(const char *prefix, const qemu_can_frame *msg)
> > }
> > qemu_log("\n");
> > qemu_log_flush();
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> >
> > static void buff2frame_pel(const uint8_t *buff, qemu_can_frame *frame)
> > diff --git a/net/can/can_socketcan.c b/net/can/can_socketcan.c
> > index 8a6ffad40c..29bfacd4f8 100644
> > --- a/net/can/can_socketcan.c
> > +++ b/net/can/can_socketcan.c
> > @@ -76,8 +76,7 @@ QEMU_BUILD_BUG_ON(offsetof(qemu_can_frame, data)
> > static void can_host_socketcan_display_msg(struct qemu_can_frame *msg)
> > {
> > int i;
> > -
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("[cansocketcan]: %03X [%01d] %s %s",
> > msg->can_id & QEMU_CAN_EFF_MASK,
> > msg->can_dlc,
> > @@ -89,7 +88,7 @@ static void can_host_socketcan_display_msg(struct qemu_can_frame *msg)
> > }
> > qemu_log("\n");
> > qemu_log_flush();
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> >
> > static void can_host_socketcan_read(void *opaque)
> > diff --git a/target/cris/translate.c b/target/cris/translate.c
> > index e752bd0609..cb57516a44 100644
> > --- a/target/cris/translate.c
> > +++ b/target/cris/translate.c
> > @@ -3273,11 +3273,11 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> > #if !DISAS_CRIS
> > if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> > && qemu_log_in_addr_range(pc_start)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("--------------\n");
> > qemu_log("IN: %s\n", lookup_symbol(pc_start));
> > log_target_disas(cs, pc_start, dc->pc - pc_start);
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> > #endif
> > diff --git a/target/i386/translate.c b/target/i386/translate.c
> > index 77e932d827..7c99ef1385 100644
> > --- a/target/i386/translate.c
> > +++ b/target/i386/translate.c
> > @@ -2502,14 +2502,15 @@ static void gen_unknown_opcode(CPUX86State *env, DisasContext *s)
> > gen_illegal_opcode(s);
> >
> > if (qemu_loglevel_mask(LOG_UNIMP)) {
> > + FILE *logfile = qemu_log_lock();
> > target_ulong pc = s->pc_start, end = s->pc;
> > - qemu_log_lock();
> > +
> > qemu_log("ILLOPC: " TARGET_FMT_lx ":", pc);
> > for (; pc < end; ++pc) {
> > qemu_log(" %02x", cpu_ldub_code(env, pc));
> > }
> > qemu_log("\n");
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > }
> >
> > diff --git a/target/lm32/translate.c b/target/lm32/translate.c
> > index 778cae1e81..73db9654d6 100644
> > --- a/target/lm32/translate.c
> > +++ b/target/lm32/translate.c
> > @@ -1137,10 +1137,10 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> > #ifdef DEBUG_DISAS
> > if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> > && qemu_log_in_addr_range(pc_start)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("\n");
> > log_target_disas(cs, pc_start, dc->pc - pc_start);
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> > }
> > diff --git a/target/microblaze/translate.c b/target/microblaze/translate.c
> > index 761f535357..cc1ad15656 100644
> > --- a/target/microblaze/translate.c
> > +++ b/target/microblaze/translate.c
> > @@ -1766,10 +1766,10 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> > #if !SIM_COMPAT
> > if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> > && qemu_log_in_addr_range(pc_start)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("--------------\n");
> > log_target_disas(cs, pc_start, dc->pc - pc_start);
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> > #endif
> > diff --git a/target/nios2/translate.c b/target/nios2/translate.c
> > index e17656e66f..82107bf270 100644
> > --- a/target/nios2/translate.c
> > +++ b/target/nios2/translate.c
> > @@ -892,11 +892,11 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> > #ifdef DEBUG_DISAS
> > if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> > && qemu_log_in_addr_range(tb->pc)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("IN: %s\n", lookup_symbol(tb->pc));
> > log_target_disas(cs, tb->pc, dc->pc - tb->pc);
> > qemu_log("\n");
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> > }
> > diff --git a/target/tilegx/translate.c b/target/tilegx/translate.c
> > index 68dd4aa2d8..fd406f4f71 100644
> > --- a/target/tilegx/translate.c
> > +++ b/target/tilegx/translate.c
> > @@ -2377,6 +2377,7 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> > uint64_t pc_start = tb->pc;
> > uint64_t page_start = pc_start & TARGET_PAGE_MASK;
> > int num_insns = 0;
> > + FILE *logfile = NULL;
> >
> > dc->pc = pc_start;
> > dc->mmuidx = 0;
> > @@ -2388,7 +2389,7 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> > dc->zero = NULL;
> >
> > if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)) {
> > - qemu_log_lock();
> > + logfile = qemu_log_lock();
> > qemu_log("IN: %s\n", lookup_symbol(pc_start));
> > }
> > gen_tb_start(tb);
> > @@ -2418,9 +2419,9 @@ void gen_intermediate_code(CPUState *cs, TranslationBlock *tb, int max_insns)
> > tb->size = dc->pc - pc_start;
> > tb->icount = num_insns;
> >
> > - if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)) {
> > + if (logfile) {
> > qemu_log("\n");
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > }
> >
> > diff --git a/target/unicore32/translate.c b/target/unicore32/translate.c
> > index 0e01f35856..0f6891b8aa 100644
> > --- a/target/unicore32/translate.c
> > +++ b/target/unicore32/translate.c
> > @@ -1994,12 +1994,12 @@ done_generating:
> > #ifdef DEBUG_DISAS
> > if (qemu_loglevel_mask(CPU_LOG_TB_IN_ASM)
> > && qemu_log_in_addr_range(pc_start)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("----------------\n");
> > qemu_log("IN: %s\n", lookup_symbol(pc_start));
> > log_target_disas(cs, pc_start, dc->pc - pc_start);
> > qemu_log("\n");
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> > tb->size = dc->pc - pc_start;
> > diff --git a/tcg/tcg.c b/tcg/tcg.c
> > index 220eaac7c7..4f616ba38b 100644
> > --- a/tcg/tcg.c
> > +++ b/tcg/tcg.c
> > @@ -1085,7 +1085,7 @@ void tcg_prologue_init(TCGContext *s)
> >
> > #ifdef DEBUG_DISAS
> > if (qemu_loglevel_mask(CPU_LOG_TB_OUT_ASM)) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("PROLOGUE: [size=%zu]\n", prologue_size);
> > if (s->data_gen_ptr) {
> > size_t code_size = s->data_gen_ptr - buf0;
> > @@ -1110,7 +1110,7 @@ void tcg_prologue_init(TCGContext *s)
> > }
> > qemu_log("\n");
> > qemu_log_flush();
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> >
> > @@ -4049,11 +4049,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
> > #ifdef DEBUG_DISAS
> > if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP)
> > && qemu_log_in_addr_range(tb->pc))) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("OP:\n");
> > tcg_dump_ops(s, false);
> > qemu_log("\n");
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> >
> > @@ -4094,11 +4094,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
> > #ifdef DEBUG_DISAS
> > if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP_IND)
> > && qemu_log_in_addr_range(tb->pc))) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("OP before indirect lowering:\n");
> > tcg_dump_ops(s, false);
> > qemu_log("\n");
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
> > /* Replace indirect temps with direct temps. */
> > @@ -4115,11 +4115,11 @@ int tcg_gen_code(TCGContext *s, TranslationBlock *tb)
> > #ifdef DEBUG_DISAS
> > if (unlikely(qemu_loglevel_mask(CPU_LOG_TB_OP_OPT)
> > && qemu_log_in_addr_range(tb->pc))) {
> > - qemu_log_lock();
> > + FILE *logfile = qemu_log_lock();
> > qemu_log("OP after optimization and liveness analysis:\n");
> > tcg_dump_ops(s, true);
> > qemu_log("\n");
> > - qemu_log_unlock();
> > + qemu_log_unlock(logfile);
> > }
> > #endif
>
>
> --
> Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 4/4] Added tests for close and change of logfile.
2019-11-07 16:32 ` Alex Bennée
2019-11-07 17:26 ` Alex Bennée
@ 2019-11-07 21:33 ` Robert Foley
1 sibling, 0 replies; 19+ messages in thread
From: Robert Foley @ 2019-11-07 21:33 UTC (permalink / raw)
To: Alex Bennée; +Cc: Peter Puhov, qemu-devel
Agree with all the suggestions below. These are great ideas. Will
make the changes.
Thanks,
-Rob Foley
On Thu, 7 Nov 2019 at 11:32, Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> Robert Foley <robert.foley@linaro.org> writes:
>
> > One test ensures that the logfile handle is still valid even if
> > the logfile is changed during logging.
> > The other test validates that the logfile handle remains valid under
> > the logfile lock even if the logfile is closed.
> >
> > Signed-off-by: Robert Foley <robert.foley@linaro.org>
> > ---
> > tests/test-logging.c | 74 ++++++++++++++++++++++++++++++++++++++++++++
> > 1 file changed, 74 insertions(+)
> >
> > diff --git a/tests/test-logging.c b/tests/test-logging.c
> > index a12585f70a..a3190ff92c 100644
> > --- a/tests/test-logging.c
> > +++ b/tests/test-logging.c
> > @@ -108,6 +108,76 @@ static void test_parse_path(gconstpointer data)
> > error_free_or_abort(&err);
> > }
> >
> > +static void test_logfile_write(gconstpointer data)
> > +{
> > + QemuLogFile *logfile;
> > + gchar const *dir = data;
> > + Error *err = NULL;
> > + gchar *file_path;
> > + gchar *file_path1;
>
> with g_autofree char *file_path you can avoid the free down bellow.
>
> > + FILE *orig_fd;
> > +
> > + file_path = g_build_filename(dir, "qemu_test_log_write0.log", NULL);
> > + file_path1 = g_build_filename(dir, "qemu_test_log_write1.log", NULL);
> > +
> > + /*
> > + * Test that even if an open file handle is changed,
> > + * our handle remains valid due to RCU.
> > + */
> > + qemu_set_log_filename(file_path, &err);
> > + g_assert(!err);
> > + rcu_read_lock();
> > + logfile = atomic_rcu_read(&qemu_logfile);
> > + orig_fd = logfile->fd;
> > + g_assert(logfile && logfile->fd);
> > + fprintf(logfile->fd, "%s 1st write to file\n", __func__);
> > + fflush(logfile->fd);
> > +
> > + /* Change the logfile and ensure that the handle is still valid. */
> > + qemu_set_log_filename(file_path1, &err);
> > + g_assert(!err);
>
> Maybe better would be:
>
> logfile2 = atomic_rcu_read(&qemu_logfile);
> g_assert(logfile->fd == orig_fd);
> g_assert(logfile2->fd != logfile->fd);
> fprintf(logfile2->fd, "%s 2nd write to file\n", __func__);
> fflush(logfile2->fd);
>
> <snip>
> > + g_assert(logfile->fd == orig_fd);
> > + fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
> > + fflush(logfile->fd);
> > + rcu_read_unlock();
> > +
> > + g_free(file_path);
> > + g_free(file_path1);
> > +}
> > +
> > +static void test_logfile_lock(gconstpointer data)
> > +{
> > + FILE *logfile;
> > + gchar const *dir = data;
> > + Error *err = NULL;
> > + gchar *file_path;
>
> g_autofree
>
> > +
> > + file_path = g_build_filename(dir, "qemu_test_logfile_lock0.log", NULL);
> > +
> > + /*
> > + * Test the use of the logfile lock, such
> > + * that even if an open file handle is closed,
> > + * our handle remains valid for use due to RCU.
> > + */
> > + qemu_set_log_filename(file_path, &err);
> > + logfile = qemu_log_lock();
> > + g_assert(logfile);
> > + fprintf(logfile, "%s 1st write to file\n", __func__);
> > + fflush(logfile);
> > +
> > + /*
> > + * Initiate a close file and make sure our handle remains
> > + * valid since we still have the logfile lock.
> > + */
> > + qemu_log_close();
> > + fprintf(logfile, "%s 2nd write to file\n", __func__);
> > + fflush(logfile);
> > + qemu_log_unlock(logfile);
> > +
> > + g_assert(!err);
> > + g_free(file_path);
> > +}
> > +
> > /* Remove a directory and all its entries (non-recursive). */
> > static void rmdir_full(gchar const *root)
> > {
> > @@ -134,6 +204,10 @@ int main(int argc, char **argv)
> >
> > g_test_add_func("/logging/parse_range", test_parse_range);
> > g_test_add_data_func("/logging/parse_path", tmp_path, test_parse_path);
> > + g_test_add_data_func("/logging/logfile_write_path",
> > + tmp_path, test_logfile_write);
> > + g_test_add_data_func("/logging/logfile_lock_path",
> > + tmp_path, test_logfile_lock);
> >
> > rc = g_test_run();
>
>
> --
> Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 1/4] Add a mutex to guarantee single writer to qemu_logfile handle.
2019-11-07 16:53 ` Alex Bennée
@ 2019-11-07 21:54 ` Robert Foley
0 siblings, 0 replies; 19+ messages in thread
From: Robert Foley @ 2019-11-07 21:54 UTC (permalink / raw)
To: Alex Bennée; +Cc: Peter Puhov, qemu-devel
On Thu, 7 Nov 2019 at 11:53, Alex Bennée <alex.bennee@linaro.org> wrote:
>
> It wouldn't be the worst thing in the world to expose:
>
> qemu_logfile_init()
>
> and make vl.c and main.c call it before the setup. Then you can drop the
> flag or even just g_assert(qemu_log_mutex_initialised) in qemu_set_log
> and qemu_set_logfile.
>
> In fact you could just use:
>
> static void __attribute__((__constructor__)) qemu_logfile_init(void)
>
> and make the compiler do it for you.
All good ideas. Will make the changes.
I agree, it is much cleaner to call init this way (constructor). We
can assert that qemu_log_mutex.initialized on use of the mutex
(qemu_set_log and qemu_set_logfile). Taking that one step further, we
could add simple helper functions for
qemu_logfile_mutex_lock()/unlock(), which g_assert() on
mutex.initialized first before lock/unlock.
Thanks,
-Rob
On Thu, 7 Nov 2019 at 11:53, Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> Robert Foley <robert.foley@linaro.org> writes:
>
> > This is being added in preparation for using RCU with the logfile handle.
> > Also added qemu_logfile_init() for initializing the logfile mutex.
> >
> > Signed-off-by: Robert Foley <robert.foley@linaro.org>
> > ---
> > util/log.c | 23 +++++++++++++++++++++++
> > 1 file changed, 23 insertions(+)
> >
> > diff --git a/util/log.c b/util/log.c
> > index 1ca13059ee..dff2f98c8c 100644
> > --- a/util/log.c
> > +++ b/util/log.c
> > @@ -24,8 +24,11 @@
> > #include "qapi/error.h"
> > #include "qemu/cutils.h"
> > #include "trace/control.h"
> > +#include "qemu/thread.h"
> >
> > static char *logfilename;
> > +static bool qemu_logfile_initialized;
> > +static QemuMutex qemu_logfile_mutex;
> > FILE *qemu_logfile;
> > int qemu_loglevel;
> > static int log_append = 0;
> > @@ -49,6 +52,14 @@ int qemu_log(const char *fmt, ...)
> > return ret;
> > }
> >
> > +static void qemu_logfile_init(void)
> > +{
> > + if (!qemu_logfile_initialized) {
> > + qemu_mutex_init(&qemu_logfile_mutex);
> > + qemu_logfile_initialized = true;
> > + }
> > +}
> > +
> > static bool log_uses_own_buffers;
> >
> > /* enable or disable low levels log */
> > @@ -58,6 +69,12 @@ void qemu_set_log(int log_flags)
> > #ifdef CONFIG_TRACE_LOG
> > qemu_loglevel |= LOG_TRACE;
> > #endif
> > +
> > + /* Is there a better place to call this to init the logfile subsystem? */
> > + if (!qemu_logfile_initialized) {
> > + qemu_logfile_init();
> > + }
>
> It wouldn't be the worst thing in the world to expose:
>
> qemu_logfile_init()
>
> and make vl.c and main.c call it before the setup. Then you can drop the
> flag or even just g_assert(qemu_log_mutex_initialised) in qemu_set_log
> and qemu_set_logfile.
>
> In fact you could just use:
>
> static void __attribute__((__constructor__)) qemu_logfile_init(void)
>
> and make the compiler do it for you.
>
> > + qemu_mutex_lock(&qemu_logfile_mutex);
> > if (!qemu_logfile &&
> > (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
> > if (logfilename) {
> > @@ -93,6 +110,7 @@ void qemu_set_log(int log_flags)
> > log_append = 1;
> > }
> > }
> > + qemu_mutex_unlock(&qemu_logfile_mutex);
> > if (qemu_logfile &&
> > (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
> > qemu_log_close();
> > @@ -114,6 +132,11 @@ void qemu_set_log_filename(const char *filename, Error **errp)
> > char *pidstr;
> > g_free(logfilename);
> >
> > + /* Is there a better place to call this to init the logfile subsystem? */
> > + if (!qemu_logfile_initialized) {
> > + qemu_logfile_init();
> > + }
> > +
> > pidstr = strstr(filename, "%");
> > if (pidstr) {
> > /* We only accept one %d, no other format strings */
>
>
> --
> Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH 4/4] Added tests for close and change of logfile.
2019-11-07 20:12 ` Alex Bennée
@ 2019-11-07 22:11 ` Robert Foley
0 siblings, 0 replies; 19+ messages in thread
From: Robert Foley @ 2019-11-07 22:11 UTC (permalink / raw)
To: Alex Bennée; +Cc: Peter Puhov, qemu-devel
On Thu, 7 Nov 2019 at 15:12, Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> > For a fix, we could put this at the beginning of qemu_set_log_filename().
> > if (logfilename) {
> > g_free(logfilename);
> > logfilename = NULL;
> > }
>
> g_free(logfilename) should be safe against NULL. However we need to
> ensure that logfilename is NULL'ed after it so we don't see the double
> free.
>
This makes sense, will remove the if (logfilename).
> > We were curious to understand why we did not see it in our own
> > testing. Although we did run make check before our first post, we did
> > not see this issue. The docker tests seem to use something like
> > MALLOC_CHECK_, which catches memory issues like this. We will be
> > sure to run the docker tests as well in the future.
>
> I was just running in my normal checkout - it could depend on how glibc
> was built for your system though. Mine is Debian Buster.
>
Interesting. We had assumed it was just the way we were running the
test. But it sounds like something about our particular setup. I'm
using Ubuntu bionic on an aarch64 system. Will look further.
Thanks,
-Rob Foley
On Thu, 7 Nov 2019 at 15:12, Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> Robert Foley <robert.foley@linaro.org> writes:
>
> > Thanks for providing the stack trace.
> >
> > We debugged this and it seems to come about because of an interesting
> > circumstance. We added our new tests after a pre-existing test,
> > parse_path(), which runs into an issue, a dangling pointer, which
> > could lead to a double free. There were no other tests after the test
> > that ran into the issue, so the double free was not exposed until we
> > added our test which called qemu_set_log_filename().
> >
> > Upon entry to qemu_set_log_filename() it frees logfilename. In the
> > case where we get an error, we return out without setting the
> > logfilename to NULL.
> > And on next call into this function we will end up with a double free.
> >
> > For a fix, we could put this at the beginning of qemu_set_log_filename().
> > if (logfilename) {
> > g_free(logfilename);
> > logfilename = NULL;
> > }
>
> g_free(logfilename) should be safe against NULL. However we need to
> ensure that logfilename is NULL'ed after it so we don't see the double
> free.
>
> > We were curious to understand why we did not see it in our own
> > testing. Although we did run make check before our first post, we did
> > not see this issue. The docker tests seem to use something like
> > MALLOC_CHECK_, which catches memory issues like this. We will be
> > sure to run the docker tests as well in the future.
>
> I was just running in my normal checkout - it could depend on how glibc
> was built for your system though. Mine is Debian Buster.
>
> >
> > On Thu, 7 Nov 2019 at 12:26, Alex Bennée <alex.bennee@linaro.org> wrote:
> >>
> >>
> >> Alex Bennée <alex.bennee@linaro.org> writes:
> >>
> >> > Robert Foley <robert.foley@linaro.org> writes:
> >> >
> >> >> One test ensures that the logfile handle is still valid even if
> >> >> the logfile is changed during logging.
> >> >> The other test validates that the logfile handle remains valid under
> >> >> the logfile lock even if the logfile is closed.
> >>
> >> Also this doesn't see to work:
> >>
> >> 17:24:31 [alex@zen:~/l/q/b/all] review/rcu-logfile|… 2 + ./tests/test-logging
> >> /logging/parse_range: OK
> >> /logging/parse_path: OK
> >> /logging/logfile_write_path: free(): double free detected in tcache 2
> >> fish: “./tests/test-logging” terminated by signal SIGABRT (Abort)
> >>
> >> in gdb
> >>
> >> Starting program: /home/alex/lsrc/qemu.git/builds/all/tests/test-logging
> >> [Thread debugging using libthread_db enabled]
> >> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
> >> [New Thread 0x7ffff6f38700 (LWP 28960)]
> >> /logging/parse_range: OK
> >> /logging/parse_path: OK
> >> /logging/logfile_write_path: free(): double free detected in tcache 2
> >>
> >> Thread 1 "test-logging" received signal SIGABRT, Aborted.
> >> __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> >> 50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
> >> (gdb) bt
> >> #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> >> #1 0x00007ffff7587535 in __GI_abort () at abort.c:79
> >> #2 0x00007ffff75de508 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7ffff76e928d "%s\n") at ../sysdeps/posix/libc_fatal.c:181
> >> #3 0x00007ffff75e4c1a in malloc_printerr (str=str@entry=0x7ffff76eaf58 "free(): double free detected in tcache 2") at malloc.c:5341
> >> #4 0x00007ffff75e66fd in _int_free (av=0x7ffff7720c40 <main_arena>, p=0x5555555cac40, have_lock=<optimized out>) at malloc.c:4193
> >> #5 0x00005555555614a8 in qemu_set_log_filename (filename=0x5555555cb110 "/tmp/qemu-test-logging.RO35A0/qemu_test_log_write0.log", errp=0x7fffffffdef0) at /home/alex/lsrc/qemu.git/util/log.c:148
> >> #6 0x000055555555d8be in test_logfile_write (data=0x5555555c7370) at /home/alex/lsrc/qemu.git/tests/test-logging.c:127
> >> #7 0x00007ffff7cdc15a in test_case_run (tc=0x5555555c9c60) at ../../../glib/gtestutils.c:2318
> >> #8 g_test_run_suite_internal (suite=suite@entry=0x5555555c8a40, path=path@entry=0x0) at ../../../glib/gtestutils.c:2403
> >> #9 0x00007ffff7cdc014 in g_test_run_suite_internal (suite=suite@entry=0x5555555c8a20, path=path@entry=0x0) at ../../../glib/gtestutils.c:2415
> >> #10 0x00007ffff7cdc412 in g_test_run_suite (suite=0x5555555c8a20) at ../../../glib/gtestutils.c:2490
> >> #11 0x00007ffff7cdc431 in g_test_run () at ../../../glib/gtestutils.c:1755
> >> #12 0x000055555555ce07 in main (argc=<optimized out>, argv=<optimized out>) at /home/alex/lsrc/qemu.git/tests/test-logging.c:212
> >>
> >>
> >> >>
> >> >> Signed-off-by: Robert Foley <robert.foley@linaro.org>
> >> >> ---
> >> >> tests/test-logging.c | 74 ++++++++++++++++++++++++++++++++++++++++++++
> >> >> 1 file changed, 74 insertions(+)
> >> >>
> >> >> diff --git a/tests/test-logging.c b/tests/test-logging.c
> >> >> index a12585f70a..a3190ff92c 100644
> >> >> --- a/tests/test-logging.c
> >> >> +++ b/tests/test-logging.c
> >> >> @@ -108,6 +108,76 @@ static void test_parse_path(gconstpointer data)
> >> >> error_free_or_abort(&err);
> >> >> }
> >> >>
> >> >> +static void test_logfile_write(gconstpointer data)
> >> >> +{
> >> >> + QemuLogFile *logfile;
> >> >> + gchar const *dir = data;
> >> >> + Error *err = NULL;
> >> >> + gchar *file_path;
> >> >> + gchar *file_path1;
> >> >
> >> > with g_autofree char *file_path you can avoid the free down bellow.
> >> >
> >> >> + FILE *orig_fd;
> >> >> +
> >> >> + file_path = g_build_filename(dir, "qemu_test_log_write0.log", NULL);
> >> >> + file_path1 = g_build_filename(dir, "qemu_test_log_write1.log", NULL);
> >> >> +
> >> >> + /*
> >> >> + * Test that even if an open file handle is changed,
> >> >> + * our handle remains valid due to RCU.
> >> >> + */
> >> >> + qemu_set_log_filename(file_path, &err);
> >> >> + g_assert(!err);
> >> >> + rcu_read_lock();
> >> >> + logfile = atomic_rcu_read(&qemu_logfile);
> >> >> + orig_fd = logfile->fd;
> >> >> + g_assert(logfile && logfile->fd);
> >> >> + fprintf(logfile->fd, "%s 1st write to file\n", __func__);
> >> >> + fflush(logfile->fd);
> >> >> +
> >> >> + /* Change the logfile and ensure that the handle is still valid. */
> >> >> + qemu_set_log_filename(file_path1, &err);
> >> >> + g_assert(!err);
> >> >
> >> > Maybe better would be:
> >> >
> >> > logfile2 = atomic_rcu_read(&qemu_logfile);
> >> > g_assert(logfile->fd == orig_fd);
> >> > g_assert(logfile2->fd != logfile->fd);
> >> > fprintf(logfile2->fd, "%s 2nd write to file\n", __func__);
> >> > fflush(logfile2->fd);
> >> >
> >> > <snip>
> >> >> + g_assert(logfile->fd == orig_fd);
> >> >> + fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
> >> >> + fflush(logfile->fd);
> >> >> + rcu_read_unlock();
> >> >> +
> >> >> + g_free(file_path);
> >> >> + g_free(file_path1);
> >> >> +}
> >> >> +
> >> >> +static void test_logfile_lock(gconstpointer data)
> >> >> +{
> >> >> + FILE *logfile;
> >> >> + gchar const *dir = data;
> >> >> + Error *err = NULL;
> >> >> + gchar *file_path;
> >> >
> >> > g_autofree
> >> >
> >> >> +
> >> >> + file_path = g_build_filename(dir, "qemu_test_logfile_lock0.log", NULL);
> >> >> +
> >> >> + /*
> >> >> + * Test the use of the logfile lock, such
> >> >> + * that even if an open file handle is closed,
> >> >> + * our handle remains valid for use due to RCU.
> >> >> + */
> >> >> + qemu_set_log_filename(file_path, &err);
> >> >> + logfile = qemu_log_lock();
> >> >> + g_assert(logfile);
> >> >> + fprintf(logfile, "%s 1st write to file\n", __func__);
> >> >> + fflush(logfile);
> >> >> +
> >> >> + /*
> >> >> + * Initiate a close file and make sure our handle remains
> >> >> + * valid since we still have the logfile lock.
> >> >> + */
> >> >> + qemu_log_close();
> >> >> + fprintf(logfile, "%s 2nd write to file\n", __func__);
> >> >> + fflush(logfile);
> >> >> + qemu_log_unlock(logfile);
> >> >> +
> >> >> + g_assert(!err);
> >> >> + g_free(file_path);
> >> >> +}
> >> >> +
> >> >> /* Remove a directory and all its entries (non-recursive). */
> >> >> static void rmdir_full(gchar const *root)
> >> >> {
> >> >> @@ -134,6 +204,10 @@ int main(int argc, char **argv)
> >> >>
> >> >> g_test_add_func("/logging/parse_range", test_parse_range);
> >> >> g_test_add_data_func("/logging/parse_path", tmp_path, test_parse_path);
> >> >> + g_test_add_data_func("/logging/logfile_write_path",
> >> >> + tmp_path, test_logfile_write);
> >> >> + g_test_add_data_func("/logging/logfile_lock_path",
> >> >> + tmp_path, test_logfile_lock);
> >> >>
> >> >> rc = g_test_run();
> >>
> >>
> >> --
> >> Alex Bennée
>
>
> --
> Alex Bennée
^ permalink raw reply [flat|nested] 19+ messages in thread
end of thread, other threads:[~2019-11-07 22:13 UTC | newest]
Thread overview: 19+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-11-07 14:26 [PATCH 0/4] Make the qemu_logfile handle thread safe Robert Foley
2019-11-07 14:26 ` [PATCH 1/4] Add a mutex to guarantee single writer to qemu_logfile handle Robert Foley
2019-11-07 16:53 ` Alex Bennée
2019-11-07 21:54 ` Robert Foley
2019-11-07 14:26 ` [PATCH 2/4] Add use of RCU for qemu_logfile Robert Foley
2019-11-07 16:23 ` Alex Bennée
2019-11-07 21:13 ` Robert Foley
2019-11-07 14:26 ` [PATCH 3/4] qemu_log_lock/unlock now preserves the qemu_logfile handle Robert Foley
2019-11-07 16:25 ` Alex Bennée
2019-11-07 21:22 ` Robert Foley
2019-11-07 14:26 ` [PATCH 4/4] Added tests for close and change of logfile Robert Foley
2019-11-07 16:32 ` Alex Bennée
2019-11-07 17:26 ` Alex Bennée
2019-11-07 19:38 ` Robert Foley
2019-11-07 20:12 ` Alex Bennée
2019-11-07 22:11 ` Robert Foley
2019-11-07 21:33 ` Robert Foley
2019-11-07 14:46 ` [PATCH 0/4] Make the qemu_logfile handle thread safe no-reply
2019-11-07 16:35 ` Alex Bennée
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.