[PATCH v1 0/5] Make the qemu_logfile handle thread safe.

[PATCH v1 0/5] Make the qemu_logfile handle thread safe.

[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.

Also added a few tests for logfile including changing the logfile
and closing the logfile.

One change also added for a pre-existing double free issue in 
qemu_set_log_filename() uncovered with the new test.

---
v1
    - This version of the patch incorporates changes 
      from the first round of review.  
    - It also includes a fix for an issue in
      qemu_set_log_filename().  This issue was uncovered 
      by the test added for this patch.
---
Robert Foley (5):
  Add a mutex to guarantee single writer to qemu_logfile handle.
  qemu_log_lock/unlock now preserves the qemu_logfile handle.
  Add use of RCU for qemu_logfile.
  Added tests for close and change of logfile.
  Fix double free issue in qemu_set_log_filename().

 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            | 49 ++++++++++++++++----
 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          | 80 ++++++++++++++++++++++++++++++++
 util/log.c                    | 86 +++++++++++++++++++++++++++--------
 18 files changed, 264 insertions(+), 69 deletions(-)

-- 
2.17.1

[PATCH v1 1/5] Add a mutex to guarantee single writer to qemu_logfile handle.

[Robert Foley]

Also added qemu_logfile_init() for initializing the logfile mutex.

Signed-off-by: Robert Foley <robert.foley@linaro.org>
---
v1
    - changed qemu_logfile_init() to use __constructor__.
---
 util/log.c | 14 ++++++++++++++
 1 file changed, 14 insertions(+)

diff --git a/util/log.c b/util/log.c
index 1ca13059ee..c25643dc99 100644
--- a/util/log.c
+++ b/util/log.c
@@ -24,8 +24,10 @@
 #include "qapi/error.h"
 #include "qemu/cutils.h"
 #include "trace/control.h"
+#include "qemu/thread.h"
 
 static char *logfilename;
+static QemuMutex qemu_logfile_mutex;
 FILE *qemu_logfile;
 int qemu_loglevel;
 static int log_append = 0;
@@ -49,6 +51,11 @@ int qemu_log(const char *fmt, ...)
     return ret;
 }
 
+static void __attribute__((__constructor__)) qemu_logfile_init(void)
+{
+    qemu_mutex_init(&qemu_logfile_mutex);
+}
+
 static bool log_uses_own_buffers;
 
 /* enable or disable low levels log */
@@ -58,6 +65,9 @@ void qemu_set_log(int log_flags)
 #ifdef CONFIG_TRACE_LOG
     qemu_loglevel |= LOG_TRACE;
 #endif
+
+    g_assert(qemu_logfile_mutex.initialized);
+    qemu_mutex_lock(&qemu_logfile_mutex);
     if (!qemu_logfile &&
         (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
         if (logfilename) {
@@ -93,6 +103,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();
@@ -230,12 +241,15 @@ void qemu_log_flush(void)
 /* Close the log file */
 void qemu_log_close(void)
 {
+    g_assert(qemu_logfile_mutex.initialized);
+    qemu_mutex_lock(&qemu_logfile_mutex);
     if (qemu_logfile) {
         if (qemu_logfile != stderr) {
             fclose(qemu_logfile);
         }
         qemu_logfile = NULL;
     }
+    qemu_mutex_unlock(&qemu_logfile_mutex);
 }
 
 const QEMULogItem qemu_log_items[] = {
-- 
2.17.1

Re: [PATCH v1 1/5] Add a mutex to guarantee single writer to qemu_logfile handle.

[Alex Bennée]

Robert Foley <robert.foley@linaro.org> writes:

> Also added qemu_logfile_init() for initializing the logfile mutex.
>
> Signed-off-by: Robert Foley <robert.foley@linaro.org>

Reviewed-by: Alex Bennée <alex.bennee@linaro.org>

> ---
> v1
>     - changed qemu_logfile_init() to use __constructor__.
> ---
>  util/log.c | 14 ++++++++++++++
>  1 file changed, 14 insertions(+)
>
> diff --git a/util/log.c b/util/log.c
> index 1ca13059ee..c25643dc99 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -24,8 +24,10 @@
>  #include "qapi/error.h"
>  #include "qemu/cutils.h"
>  #include "trace/control.h"
> +#include "qemu/thread.h"
>
>  static char *logfilename;
> +static QemuMutex qemu_logfile_mutex;
>  FILE *qemu_logfile;
>  int qemu_loglevel;
>  static int log_append = 0;
> @@ -49,6 +51,11 @@ int qemu_log(const char *fmt, ...)
>      return ret;
>  }
>
> +static void __attribute__((__constructor__)) qemu_logfile_init(void)
> +{
> +    qemu_mutex_init(&qemu_logfile_mutex);
> +}
> +
>  static bool log_uses_own_buffers;
>
>  /* enable or disable low levels log */
> @@ -58,6 +65,9 @@ void qemu_set_log(int log_flags)
>  #ifdef CONFIG_TRACE_LOG
>      qemu_loglevel |= LOG_TRACE;
>  #endif
> +
> +    g_assert(qemu_logfile_mutex.initialized);
> +    qemu_mutex_lock(&qemu_logfile_mutex);
>      if (!qemu_logfile &&
>          (is_daemonized() ? logfilename != NULL : qemu_loglevel)) {
>          if (logfilename) {
> @@ -93,6 +103,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();
> @@ -230,12 +241,15 @@ void qemu_log_flush(void)
>  /* Close the log file */
>  void qemu_log_close(void)
>  {
> +    g_assert(qemu_logfile_mutex.initialized);
> +    qemu_mutex_lock(&qemu_logfile_mutex);
>      if (qemu_logfile) {
>          if (qemu_logfile != stderr) {
>              fclose(qemu_logfile);
>          }
>          qemu_logfile = NULL;
>      }
> +    qemu_mutex_unlock(&qemu_logfile_mutex);
>  }
>
>  const QEMULogItem qemu_log_items[] = {


--
Alex Bennée

Re: [PATCH v1 1/5] Add a mutex to guarantee single writer to qemu_logfile handle.

[Richard Henderson]

On 11/12/19 4:01 PM, Robert Foley wrote:
> Also added qemu_logfile_init() for initializing the logfile mutex.
> 
> Signed-off-by: Robert Foley <robert.foley@linaro.org>
> ---
> v1
>     - changed qemu_logfile_init() to use __constructor__.
> ---
>  util/log.c | 14 ++++++++++++++
>  1 file changed, 14 insertions(+)
> 
> diff --git a/util/log.c b/util/log.c
> index 1ca13059ee..c25643dc99 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -24,8 +24,10 @@
>  #include "qapi/error.h"
>  #include "qemu/cutils.h"
>  #include "trace/control.h"
> +#include "qemu/thread.h"
>  
>  static char *logfilename;
> +static QemuMutex qemu_logfile_mutex;
>  FILE *qemu_logfile;
>  int qemu_loglevel;
>  static int log_append = 0;
> @@ -49,6 +51,11 @@ int qemu_log(const char *fmt, ...)
>      return ret;
>  }
>  
> +static void __attribute__((__constructor__)) qemu_logfile_init(void)
> +{
> +    qemu_mutex_init(&qemu_logfile_mutex);
> +}
> +
>  static bool log_uses_own_buffers;
>  
>  /* enable or disable low levels log */
> @@ -58,6 +65,9 @@ void qemu_set_log(int log_flags)
>  #ifdef CONFIG_TRACE_LOG
>      qemu_loglevel |= LOG_TRACE;
>  #endif
> +
> +    g_assert(qemu_logfile_mutex.initialized);

Why the asserts?

If you want a runtime test, then use the test to initialize it.
Otherwise, trust the constructor.


r~

Re: [PATCH v1 1/5] Add a mutex to guarantee single writer to qemu_logfile handle.

[Robert Foley]

> > +
> > +    g_assert(qemu_logfile_mutex.initialized);
>
> Why the asserts?
>
> If you want a runtime test, then use the test to initialize it.
> Otherwise, trust the constructor.
>
I see your point here.   We can/should just trust the constructor.
Will remove the mutex.initialized asserts.

Thanks,
-Rob

On Sat, 16 Nov 2019 at 06:58, Richard Henderson
<richard.henderson@linaro.org> wrote:
>
> On 11/12/19 4:01 PM, Robert Foley wrote:
> > Also added qemu_logfile_init() for initializing the logfile mutex.
> >
> > Signed-off-by: Robert Foley <robert.foley@linaro.org>
> > ---
> > v1
> >     - changed qemu_logfile_init() to use __constructor__.
> > ---
> >  util/log.c | 14 ++++++++++++++
> >  1 file changed, 14 insertions(+)
> >
> > diff --git a/util/log.c b/util/log.c
> > index 1ca13059ee..c25643dc99 100644
> > --- a/util/log.c
> > +++ b/util/log.c
> > @@ -24,8 +24,10 @@
> >  #include "qapi/error.h"
> >  #include "qemu/cutils.h"
> >  #include "trace/control.h"
> > +#include "qemu/thread.h"
> >
> >  static char *logfilename;
> > +static QemuMutex qemu_logfile_mutex;
> >  FILE *qemu_logfile;
> >  int qemu_loglevel;
> >  static int log_append = 0;
> > @@ -49,6 +51,11 @@ int qemu_log(const char *fmt, ...)
> >      return ret;
> >  }
> >
> > +static void __attribute__((__constructor__)) qemu_logfile_init(void)
> > +{
> > +    qemu_mutex_init(&qemu_logfile_mutex);
> > +}
> > +
> >  static bool log_uses_own_buffers;
> >
> >  /* enable or disable low levels log */
> > @@ -58,6 +65,9 @@ void qemu_set_log(int log_flags)
> >  #ifdef CONFIG_TRACE_LOG
> >      qemu_loglevel |= LOG_TRACE;
> >  #endif
> > +
> > +    g_assert(qemu_logfile_mutex.initialized);
>
> Why the asserts?
>
> If you want a runtime test, then use the test to initialize it.
> Otherwise, trust the constructor.
>
>
> r~

[PATCH v1 2/5] qemu_log_lock/unlock now preserves the qemu_logfile handle.

[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>
---
v1
    - Moved this up in the patch sequence to be
      before adding RCU for qemu_logfile.
---
 include/qemu/log.h            |  9 ++++++---
 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, 43 insertions(+), 39 deletions(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index a91105b2ad..a7c5b01571 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -53,14 +53,17 @@ 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)
 {
     qemu_flockfile(qemu_logfile);
+    return logfile->fd;
 }
 
-static inline void qemu_log_unlock(void)
+static inline void qemu_log_unlock(FILE *fd)
 {
-    qemu_funlockfile(qemu_logfile);
+    if (fd) {
+        qemu_funlockfile(fd);
+    }
 }
 
 /* Logging functions: */
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/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/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 5475d49ed1..0511266d85 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
 
@@ -4041,11 +4041,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
 
@@ -4086,11 +4086,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.  */
@@ -4107,11 +4107,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

Re: [PATCH v1 2/5] qemu_log_lock/unlock now preserves the qemu_logfile handle.

[Alex Bennée]

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.
>
> Signed-off-by: Robert Foley <robert.foley@linaro.org>
> ---
> v1
>     - Moved this up in the patch sequence to be
>       before adding RCU for qemu_logfile.
> ---
>  include/qemu/log.h            |  9 ++++++---
>  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 ++--

A bit messier than I'd like but I guess that's unavoidable. It does
nicely show who's left to convert to the common translator loop ;-)

Reviewed-by: Alex Bennée <alex.bennee@linaro.org>

>  tcg/tcg.c                     | 16 ++++++++--------
>  15 files changed, 43 insertions(+), 39 deletions(-)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index a91105b2ad..a7c5b01571 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -53,14 +53,17 @@ 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)
>  {
>      qemu_flockfile(qemu_logfile);
> +    return logfile->fd;
>  }
>
> -static inline void qemu_log_unlock(void)
> +static inline void qemu_log_unlock(FILE *fd)
>  {
> -    qemu_funlockfile(qemu_logfile);
> +    if (fd) {
> +        qemu_funlockfile(fd);
> +    }
>  }
>
>  /* Logging functions: */
> 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/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/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 5475d49ed1..0511266d85 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
>
> @@ -4041,11 +4041,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
>
> @@ -4086,11 +4086,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.  */
> @@ -4107,11 +4107,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

Re: [PATCH v1 2/5] qemu_log_lock/unlock now preserves the qemu_logfile handle.

[Richard Henderson]

On 11/12/19 4:01 PM, Robert Foley wrote:
> 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>
> ---
> v1
>     - Moved this up in the patch sequence to be
>       before adding RCU for qemu_logfile.
> ---

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>


r~

[PATCH v1 3/5] Add use of RCU for qemu_logfile.

[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>
---
v1
    - Changes for review comments.
    - Minor changes to definition of QemuLogFile.
    - Changed qemu_log_separate() to fix unbalanced and 
      remove qemu_log_enabled() check.
    - changed qemu_log_lock() to include else.
    - make qemu_logfile_free static.
    - use g_assert(logfile) in qemu_logfile_free.
    - Relocated unlock out of if/else in qemu_log_close(), and
      in qemu_set_log().
---
 include/qemu/log.h | 42 ++++++++++++++++++++++----
 util/log.c         | 73 +++++++++++++++++++++++++++++++++-------------
 include/exec/log.h | 33 ++++++++++++++++++---
 tcg/tcg.c          | 12 ++++++--
 4 files changed, 128 insertions(+), 32 deletions(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index a7c5b01571..528e1f9dd7 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -3,9 +3,16 @@
 
 /* A small part of this API is split into its own header */
 #include "qemu/log-for-trace.h"
+#include "qemu/rcu.h"
+
+typedef struct QemuLogFile {
+    struct rcu_head rcu;
+    FILE *fd;
+} QemuLogFile;
 
 /* Private global variable, don't use */
-extern FILE *qemu_logfile;
+extern QemuLogFile *qemu_logfile;
+
 
 /* 
  * The new API:
@@ -25,7 +32,16 @@ static inline bool qemu_log_enabled(void)
  */
 static inline bool qemu_log_separate(void)
 {
-    return qemu_logfile != NULL && qemu_logfile != stderr;
+    QemuLogFile *logfile;
+    bool res = false;
+
+    rcu_read_lock();
+    logfile = atomic_rcu_read(&qemu_logfile);
+    if (logfile && logfile->fd != stderr) {
+        res = true;
+    }
+    rcu_read_unlock();
+    return res;
 }
 
 #define CPU_LOG_TB_OUT_ASM (1 << 0)
@@ -55,14 +71,23 @@ static inline bool qemu_log_separate(void)
 
 static inline FILE *qemu_log_lock(void)
 {
-    qemu_flockfile(qemu_logfile);
-    return logfile->fd;
+    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 void qemu_log_unlock(FILE *fd)
 {
     if (fd) {
         qemu_funlockfile(fd);
+        rcu_read_unlock();
     }
 }
 
@@ -73,9 +98,14 @@ static inline void qemu_log_unlock(FILE *fd)
 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:
diff --git a/util/log.c b/util/log.c
index c25643dc99..802b8de42e 100644
--- a/util/log.c
+++ b/util/log.c
@@ -28,7 +28,7 @@
 
 static char *logfilename;
 static QemuMutex qemu_logfile_mutex;
-FILE *qemu_logfile;
+QemuLogFile *qemu_logfile;
 int qemu_loglevel;
 static int log_append = 0;
 static GArray *debug_regions;
@@ -37,10 +37,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.  */
@@ -48,6 +52,7 @@ int qemu_log(const char *fmt, ...)
             ret = 0;
         }
     }
+    rcu_read_unlock();
     return ret;
 }
 
@@ -56,11 +61,23 @@ static void __attribute__((__constructor__)) qemu_logfile_init(void)
     qemu_mutex_init(&qemu_logfile_mutex);
 }
 
+static void qemu_logfile_free(QemuLogFile *logfile)
+{
+    g_assert(logfile);
+
+    if (logfile->fd != stderr) {
+        fclose(logfile->fd);
+    }
+    g_free(logfile);
+}
+
 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;
@@ -70,44 +87,50 @@ 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);
+        call_rcu(logfile, qemu_logfile_free, rcu);
     }
+    qemu_mutex_unlock(&qemu_logfile_mutex);
 }
 
 void qemu_log_needs_buffers(void)
@@ -123,6 +146,7 @@ void qemu_log_needs_buffers(void)
 void qemu_set_log_filename(const char *filename, Error **errp)
 {
     char *pidstr;
+
     g_free(logfilename);
 
     pidstr = strstr(filename, "%");
@@ -235,19 +259,28 @@ 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();
 }
 
 /* Close the log file */
 void qemu_log_close(void)
 {
+    QemuLogFile *logfile;
+
     g_assert(qemu_logfile_mutex.initialized);
     qemu_mutex_lock(&qemu_logfile_mutex);
-    if (qemu_logfile) {
-        if (qemu_logfile != stderr) {
-            fclose(qemu_logfile);
-        }
-        qemu_logfile = NULL;
+    logfile = qemu_logfile;
+
+    if (logfile) {
+        atomic_rcu_set(&qemu_logfile, NULL);
+        call_rcu(logfile, qemu_logfile_free, rcu);
     }
     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 0511266d85..4f616ba38b 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

Re: [PATCH v1 3/5] Add use of RCU for qemu_logfile.

[Alex Bennée]

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>
> ---
> v1
>     - Changes for review comments.
>     - Minor changes to definition of QemuLogFile.
>     - Changed qemu_log_separate() to fix unbalanced and
>       remove qemu_log_enabled() check.
>     - changed qemu_log_lock() to include else.
>     - make qemu_logfile_free static.
>     - use g_assert(logfile) in qemu_logfile_free.
>     - Relocated unlock out of if/else in qemu_log_close(), and
>       in qemu_set_log().
> ---
>  include/qemu/log.h | 42 ++++++++++++++++++++++----
>  util/log.c         | 73 +++++++++++++++++++++++++++++++++-------------
>  include/exec/log.h | 33 ++++++++++++++++++---
>  tcg/tcg.c          | 12 ++++++--
>  4 files changed, 128 insertions(+), 32 deletions(-)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index a7c5b01571..528e1f9dd7 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -3,9 +3,16 @@
>
>  /* A small part of this API is split into its own header */
>  #include "qemu/log-for-trace.h"
> +#include "qemu/rcu.h"
> +
> +typedef struct QemuLogFile {
> +    struct rcu_head rcu;
> +    FILE *fd;
> +} QemuLogFile;
>
>  /* Private global variable, don't use */
> -extern FILE *qemu_logfile;
> +extern QemuLogFile *qemu_logfile;
> +
>
>  /*
>   * The new API:
> @@ -25,7 +32,16 @@ static inline bool qemu_log_enabled(void)
>   */
>  static inline bool qemu_log_separate(void)
>  {
> -    return qemu_logfile != NULL && qemu_logfile != stderr;
> +    QemuLogFile *logfile;
> +    bool res = false;
> +
> +    rcu_read_lock();
> +    logfile = atomic_rcu_read(&qemu_logfile);
> +    if (logfile && logfile->fd != stderr) {
> +        res = true;
> +    }
> +    rcu_read_unlock();
> +    return res;
>  }
>
>  #define CPU_LOG_TB_OUT_ASM (1 << 0)
> @@ -55,14 +71,23 @@ static inline bool qemu_log_separate(void)
>
>  static inline FILE *qemu_log_lock(void)
>  {
> -    qemu_flockfile(qemu_logfile);
> -    return logfile->fd;
> +    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 void qemu_log_unlock(FILE *fd)
>  {
>      if (fd) {
>          qemu_funlockfile(fd);
> +        rcu_read_unlock();
>      }
>  }
>
> @@ -73,9 +98,14 @@ static inline void qemu_log_unlock(FILE *fd)
>  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:
> diff --git a/util/log.c b/util/log.c
> index c25643dc99..802b8de42e 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -28,7 +28,7 @@
>
>  static char *logfilename;
>  static QemuMutex qemu_logfile_mutex;
> -FILE *qemu_logfile;
> +QemuLogFile *qemu_logfile;
>  int qemu_loglevel;
>  static int log_append = 0;
>  static GArray *debug_regions;
> @@ -37,10 +37,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.  */
> @@ -48,6 +52,7 @@ int qemu_log(const char *fmt, ...)
>              ret = 0;
>          }
>      }
> +    rcu_read_unlock();
>      return ret;
>  }
>
> @@ -56,11 +61,23 @@ static void __attribute__((__constructor__)) qemu_logfile_init(void)
>      qemu_mutex_init(&qemu_logfile_mutex);
>  }
>
> +static void qemu_logfile_free(QemuLogFile *logfile)
> +{
> +    g_assert(logfile);
> +
> +    if (logfile->fd != stderr) {
> +        fclose(logfile->fd);
> +    }
> +    g_free(logfile);
> +}
> +
>  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;
> @@ -70,44 +87,50 @@ 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;

Isn't this read outside of the protection of both rcu_read_lock() and
the mutex? Could that race?

> +
>      if (qemu_logfile &&
>          (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
> -        qemu_log_close();
> +        atomic_rcu_set(&qemu_logfile, NULL);
> +        call_rcu(logfile, qemu_logfile_free, rcu);

I wonder if we can re-arrange the logic here so it's lets confusing? For
example the NULL qemu_loglevel can be detected at the start and we
should be able just to squash the current log and reset and go. I'm not
sure about the damonize/stdout check.

>      }
> +    qemu_mutex_unlock(&qemu_logfile_mutex);
>  }
>
>  void qemu_log_needs_buffers(void)
> @@ -123,6 +146,7 @@ void qemu_log_needs_buffers(void)
>  void qemu_set_log_filename(const char *filename, Error **errp)
>  {
>      char *pidstr;
> +
>      g_free(logfilename);

nit: stray newline
>
>      pidstr = strstr(filename, "%");
> @@ -235,19 +259,28 @@ 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();
>  }
>
>  /* Close the log file */
>  void qemu_log_close(void)
>  {
> +    QemuLogFile *logfile;
> +
>      g_assert(qemu_logfile_mutex.initialized);
>      qemu_mutex_lock(&qemu_logfile_mutex);
> -    if (qemu_logfile) {
> -        if (qemu_logfile != stderr) {
> -            fclose(qemu_logfile);
> -        }
> -        qemu_logfile = NULL;
> +    logfile = qemu_logfile;
> +
> +    if (logfile) {
> +        atomic_rcu_set(&qemu_logfile, NULL);
> +        call_rcu(logfile, qemu_logfile_free, rcu);
>      }
>      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 0511266d85..4f616ba38b 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) {


--
Alex Bennée

Re: [PATCH v1 3/5] Add use of RCU for qemu_logfile.

[Robert Foley]

On Tue, 12 Nov 2019 at 12:36, Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> >          }
> > +        atomic_rcu_set(&qemu_logfile, logfile);
> >      }
> > -    qemu_mutex_unlock(&qemu_logfile_mutex);
> > +    logfile = qemu_logfile;
>
> Isn't this read outside of the protection of both rcu_read_lock() and
> the mutex? Could that race?

This assignment is under the mutex.  This change moved the mutex
unlock towards the end of the function, just a few lines below the
call_rcu().

> > +
> >      if (qemu_logfile &&
> >          (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
> > -        qemu_log_close();
> > +        atomic_rcu_set(&qemu_logfile, NULL);
> > +        call_rcu(logfile, qemu_logfile_free, rcu);
>
> I wonder if we can re-arrange the logic here so it's lets confusing? For
> example the NULL qemu_loglevel can be detected at the start and we
> should be able just to squash the current log and reset and go. I'm not
> sure about the damonize/stdout check.
>
> >      }
> > +    qemu_mutex_unlock(&qemu_logfile_mutex);
> >  }
> >

Absolutely, the logic that was here originally can be improved.  We
found it confusing also.
We could move things around a bit and change it to something like this
to help clarify.

    bool need_to_open_file = false;
    /*
     * In all cases we only log if qemu_loglevel is set.
     * And:
     *     If not daemonized we will always log either to stderr
     *       or to a file (if there is a logfilename).
     *     If we are daemonized,
     *       we will only log if there is a logfilename.
     */
    if (qemu_loglevel && (!is_daemonized() || logfilename) {
        need_to_open_file = true;
    }
    g_assert(qemu_logfile_mutex.initialized);
    qemu_mutex_lock(&qemu_logfile_mutex);

    if(qemu_logfile && !need_to_open_file) {
        /* Close file. */
        QemuLogFile *logfile = qemu_logfile;
        atomic_rcu_set(&qemu_logfile, NULL);
        call_rcu(logfile, qemu_logfile_free, rcu);
    } else if(!qemu_logfile && need_to_open_file) {
        logfile = g_new0(QemuLogFile, 1);
       __snip__ existing patch logic for opening the qemu_logfile will
be inserted here.
    }
    qemu_mutex_unlock(&qemu_logfile_mutex);

> >  {
> >      char *pidstr;
> > +
> >      g_free(logfilename);
>
> nit: stray newline

Will remove the newline.

Thanks,
Rob

On Tue, 12 Nov 2019 at 12:36, Alex Bennée <alex.bennee@linaro.org> wrote:
>
>
> 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>
> > ---
> > v1
> >     - Changes for review comments.
> >     - Minor changes to definition of QemuLogFile.
> >     - Changed qemu_log_separate() to fix unbalanced and
> >       remove qemu_log_enabled() check.
> >     - changed qemu_log_lock() to include else.
> >     - make qemu_logfile_free static.
> >     - use g_assert(logfile) in qemu_logfile_free.
> >     - Relocated unlock out of if/else in qemu_log_close(), and
> >       in qemu_set_log().
> > ---
> >  include/qemu/log.h | 42 ++++++++++++++++++++++----
> >  util/log.c         | 73 +++++++++++++++++++++++++++++++++-------------
> >  include/exec/log.h | 33 ++++++++++++++++++---
> >  tcg/tcg.c          | 12 ++++++--
> >  4 files changed, 128 insertions(+), 32 deletions(-)
> >
> > diff --git a/include/qemu/log.h b/include/qemu/log.h
> > index a7c5b01571..528e1f9dd7 100644
> > --- a/include/qemu/log.h
> > +++ b/include/qemu/log.h
> > @@ -3,9 +3,16 @@
> >
> >  /* A small part of this API is split into its own header */
> >  #include "qemu/log-for-trace.h"
> > +#include "qemu/rcu.h"
> > +
> > +typedef struct QemuLogFile {
> > +    struct rcu_head rcu;
> > +    FILE *fd;
> > +} QemuLogFile;
> >
> >  /* Private global variable, don't use */
> > -extern FILE *qemu_logfile;
> > +extern QemuLogFile *qemu_logfile;
> > +
> >
> >  /*
> >   * The new API:
> > @@ -25,7 +32,16 @@ static inline bool qemu_log_enabled(void)
> >   */
> >  static inline bool qemu_log_separate(void)
> >  {
> > -    return qemu_logfile != NULL && qemu_logfile != stderr;
> > +    QemuLogFile *logfile;
> > +    bool res = false;
> > +
> > +    rcu_read_lock();
> > +    logfile = atomic_rcu_read(&qemu_logfile);
> > +    if (logfile && logfile->fd != stderr) {
> > +        res = true;
> > +    }
> > +    rcu_read_unlock();
> > +    return res;
> >  }
> >
> >  #define CPU_LOG_TB_OUT_ASM (1 << 0)
> > @@ -55,14 +71,23 @@ static inline bool qemu_log_separate(void)
> >
> >  static inline FILE *qemu_log_lock(void)
> >  {
> > -    qemu_flockfile(qemu_logfile);
> > -    return logfile->fd;
> > +    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 void qemu_log_unlock(FILE *fd)
> >  {
> >      if (fd) {
> >          qemu_funlockfile(fd);
> > +        rcu_read_unlock();
> >      }
> >  }
> >
> > @@ -73,9 +98,14 @@ static inline void qemu_log_unlock(FILE *fd)
> >  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:
> > diff --git a/util/log.c b/util/log.c
> > index c25643dc99..802b8de42e 100644
> > --- a/util/log.c
> > +++ b/util/log.c
> > @@ -28,7 +28,7 @@
> >
> >  static char *logfilename;
> >  static QemuMutex qemu_logfile_mutex;
> > -FILE *qemu_logfile;
> > +QemuLogFile *qemu_logfile;
> >  int qemu_loglevel;
> >  static int log_append = 0;
> >  static GArray *debug_regions;
> > @@ -37,10 +37,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.  */
> > @@ -48,6 +52,7 @@ int qemu_log(const char *fmt, ...)
> >              ret = 0;
> >          }
> >      }
> > +    rcu_read_unlock();
> >      return ret;
> >  }
> >
> > @@ -56,11 +61,23 @@ static void __attribute__((__constructor__)) qemu_logfile_init(void)
> >      qemu_mutex_init(&qemu_logfile_mutex);
> >  }
> >
> > +static void qemu_logfile_free(QemuLogFile *logfile)
> > +{
> > +    g_assert(logfile);
> > +
> > +    if (logfile->fd != stderr) {
> > +        fclose(logfile->fd);
> > +    }
> > +    g_free(logfile);
> > +}
> > +
> >  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;
> > @@ -70,44 +87,50 @@ 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;
>
> Isn't this read outside of the protection of both rcu_read_lock() and
> the mutex? Could that race?
>
> > +
> >      if (qemu_logfile &&
> >          (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
> > -        qemu_log_close();
> > +        atomic_rcu_set(&qemu_logfile, NULL);
> > +        call_rcu(logfile, qemu_logfile_free, rcu);
>
> I wonder if we can re-arrange the logic here so it's lets confusing? For
> example the NULL qemu_loglevel can be detected at the start and we
> should be able just to squash the current log and reset and go. I'm not
> sure about the damonize/stdout check.
>
> >      }
> > +    qemu_mutex_unlock(&qemu_logfile_mutex);
> >  }
> >
> >  void qemu_log_needs_buffers(void)
> > @@ -123,6 +146,7 @@ void qemu_log_needs_buffers(void)
> >  void qemu_set_log_filename(const char *filename, Error **errp)
> >  {
> >      char *pidstr;
> > +
> >      g_free(logfilename);
>
> nit: stray newline
> >
> >      pidstr = strstr(filename, "%");
> > @@ -235,19 +259,28 @@ 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();
> >  }
> >
> >  /* Close the log file */
> >  void qemu_log_close(void)
> >  {
> > +    QemuLogFile *logfile;
> > +
> >      g_assert(qemu_logfile_mutex.initialized);
> >      qemu_mutex_lock(&qemu_logfile_mutex);
> > -    if (qemu_logfile) {
> > -        if (qemu_logfile != stderr) {
> > -            fclose(qemu_logfile);
> > -        }
> > -        qemu_logfile = NULL;
> > +    logfile = qemu_logfile;
> > +
> > +    if (logfile) {
> > +        atomic_rcu_set(&qemu_logfile, NULL);
> > +        call_rcu(logfile, qemu_logfile_free, rcu);
> >      }
> >      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 0511266d85..4f616ba38b 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) {
>
>
> --
> Alex Bennée

Re: [PATCH v1 3/5] Add use of RCU for qemu_logfile.

[Alex Bennée]

Robert Foley <robert.foley@linaro.org> writes:

> On Tue, 12 Nov 2019 at 12:36, Alex Bennée <alex.bennee@linaro.org> wrote:
>>
>>
>> >          }
>> > +        atomic_rcu_set(&qemu_logfile, logfile);
>> >      }
>> > -    qemu_mutex_unlock(&qemu_logfile_mutex);
>> > +    logfile = qemu_logfile;
>>
>> Isn't this read outside of the protection of both rcu_read_lock() and
>> the mutex? Could that race?
>
> This assignment is under the mutex.  This change moved the mutex
> unlock towards the end of the function, just a few lines below the
> call_rcu().

Ahh I see now, I went +- blind ;-)

>
>> > +
>> >      if (qemu_logfile &&
>> >          (is_daemonized() ? logfilename == NULL : !qemu_loglevel)) {
>> > -        qemu_log_close();
>> > +        atomic_rcu_set(&qemu_logfile, NULL);
>> > +        call_rcu(logfile, qemu_logfile_free, rcu);
>>
>> I wonder if we can re-arrange the logic here so it's lets confusing? For
>> example the NULL qemu_loglevel can be detected at the start and we
>> should be able just to squash the current log and reset and go. I'm not
>> sure about the damonize/stdout check.
>>
>> >      }
>> > +    qemu_mutex_unlock(&qemu_logfile_mutex);
>> >  }
>> >
>
> Absolutely, the logic that was here originally can be improved.  We
> found it confusing also.
> We could move things around a bit and change it to something like this
> to help clarify.
>
>     bool need_to_open_file = false;
>     /*
>      * In all cases we only log if qemu_loglevel is set.
>      * And:
>      *     If not daemonized we will always log either to stderr
>      *       or to a file (if there is a logfilename).
>      *     If we are daemonized,
>      *       we will only log if there is a logfilename.
>      */
>     if (qemu_loglevel && (!is_daemonized() || logfilename) {
>         need_to_open_file = true;
>     }
>     g_assert(qemu_logfile_mutex.initialized);
>     qemu_mutex_lock(&qemu_logfile_mutex);
>
>     if(qemu_logfile && !need_to_open_file) {
>         /* Close file. */
>         QemuLogFile *logfile = qemu_logfile;
>         atomic_rcu_set(&qemu_logfile, NULL);
>         call_rcu(logfile, qemu_logfile_free, rcu);
>     } else if(!qemu_logfile && need_to_open_file) {
>         logfile = g_new0(QemuLogFile, 1);
>        __snip__ existing patch logic for opening the qemu_logfile will
> be inserted here.
>     }
>     qemu_mutex_unlock(&qemu_logfile_mutex);

That reads a lot better thanks. It's probably worth doing the clean-up in
a separate patch so it is easier to see the mutex's when added.

--
Alex Bennée

[PATCH v1 4/5] Added tests for close and change of logfile.

[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>
--
v1
    - Changes for first round of code review comments.
    - Added in use of g_autofree, removed the g_free()s.
    - Added in use of logfile2 and changed sequence of asserts.
---
 tests/test-logging.c | 80 ++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 80 insertions(+)

diff --git a/tests/test-logging.c b/tests/test-logging.c
index a12585f70a..1e646f045d 100644
--- a/tests/test-logging.c
+++ b/tests/test-logging.c
@@ -108,6 +108,82 @@ static void test_parse_path(gconstpointer data)
     error_free_or_abort(&err);
 }
 
+static void test_logfile_write(gconstpointer data)
+{
+    QemuLogFile *logfile;
+    QemuLogFile *logfile2;
+    gchar const *dir = data;
+    Error *err = NULL;
+    g_autofree gchar *file_path;
+    g_autofree gchar *file_path1;
+    FILE *orig_fd;
+
+    /*
+     * Before starting test, set log flags, to ensure the file gets
+     * opened below with the call to qemu_set_log_filename().
+     * In cases where a logging backend other than log is used,
+     * this is needed.
+     */
+    qemu_set_log(CPU_LOG_TB_OUT_ASM);
+    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);
+    logfile2 = atomic_rcu_read(&qemu_logfile);
+    g_assert(logfile->fd == orig_fd);
+    g_assert(logfile2->fd != logfile->fd);
+    fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
+    fflush(logfile->fd);
+    rcu_read_unlock();
+}
+
+static void test_logfile_lock(gconstpointer data)
+{
+    FILE *logfile;
+    gchar const *dir = data;
+    Error *err = NULL;
+    g_autofree 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);
+}
+
 /* Remove a directory and all its entries (non-recursive). */
 static void rmdir_full(gchar const *root)
 {
@@ -134,6 +210,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

Re: [PATCH v1 4/5] Added tests for close and change of logfile.

[Alex Bennée]

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>

Reviewed-by: Alex Bennée <alex.bennee@linaro.org>

> --
> v1
>     - Changes for first round of code review comments.
>     - Added in use of g_autofree, removed the g_free()s.
>     - Added in use of logfile2 and changed sequence of asserts.
> ---
>  tests/test-logging.c | 80 ++++++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 80 insertions(+)
>
> diff --git a/tests/test-logging.c b/tests/test-logging.c
> index a12585f70a..1e646f045d 100644
> --- a/tests/test-logging.c
> +++ b/tests/test-logging.c
> @@ -108,6 +108,82 @@ static void test_parse_path(gconstpointer data)
>      error_free_or_abort(&err);
>  }
>
> +static void test_logfile_write(gconstpointer data)
> +{
> +    QemuLogFile *logfile;
> +    QemuLogFile *logfile2;
> +    gchar const *dir = data;
> +    Error *err = NULL;
> +    g_autofree gchar *file_path;
> +    g_autofree gchar *file_path1;
> +    FILE *orig_fd;
> +
> +    /*
> +     * Before starting test, set log flags, to ensure the file gets
> +     * opened below with the call to qemu_set_log_filename().
> +     * In cases where a logging backend other than log is used,
> +     * this is needed.
> +     */
> +    qemu_set_log(CPU_LOG_TB_OUT_ASM);
> +    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);
> +    logfile2 = atomic_rcu_read(&qemu_logfile);
> +    g_assert(logfile->fd == orig_fd);
> +    g_assert(logfile2->fd != logfile->fd);
> +    fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
> +    fflush(logfile->fd);
> +    rcu_read_unlock();
> +}
> +
> +static void test_logfile_lock(gconstpointer data)
> +{
> +    FILE *logfile;
> +    gchar const *dir = data;
> +    Error *err = NULL;
> +    g_autofree 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);
> +}
> +
>  /* Remove a directory and all its entries (non-recursive). */
>  static void rmdir_full(gchar const *root)
>  {
> @@ -134,6 +210,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

[PATCH v1 5/5] Fix double free issue in qemu_set_log_filename().

[Robert Foley]

After freeing the logfilename, we set logfilename to NULL, in case of an
error which returns without setting logfilename.

Signed-off-by: Robert Foley <robert.foley@linaro.org>
---
v1
    - This is new in the patch v1.
---
 util/log.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/util/log.c b/util/log.c
index 802b8de42e..1eed74788c 100644
--- a/util/log.c
+++ b/util/log.c
@@ -148,6 +148,7 @@ void qemu_set_log_filename(const char *filename, Error **errp)
     char *pidstr;
 
     g_free(logfilename);
+    logfilename = NULL;
 
     pidstr = strstr(filename, "%");
     if (pidstr) {
-- 
2.17.1

Re: [PATCH v1 5/5] Fix double free issue in qemu_set_log_filename().

[Alex Bennée]

Robert Foley <robert.foley@linaro.org> writes:

> After freeing the logfilename, we set logfilename to NULL, in case of an
> error which returns without setting logfilename.
>
> Signed-off-by: Robert Foley <robert.foley@linaro.org>

As this fixes an existing bug I would put this at the start of the
series. Otherwise:

Reviewed-by: Alex Bennée <alex.bennee@linaro.org>

> ---
> v1
>     - This is new in the patch v1.
> ---
>  util/log.c | 1 +
>  1 file changed, 1 insertion(+)
>
> diff --git a/util/log.c b/util/log.c
> index 802b8de42e..1eed74788c 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -148,6 +148,7 @@ void qemu_set_log_filename(const char *filename, Error **errp)
>      char *pidstr;
>
>      g_free(logfilename);
> +    logfilename = NULL;
>
>      pidstr = strstr(filename, "%");
>      if (pidstr) {


--
Alex Bennée