[PATCH v3 0/2] util/log: Always send errors to logfile when daemonized

[PATCH v3 0/2] util/log: Always send errors to logfile when daemonized

[Greg Kurz]

When QEMU is started with `--daemonize -D ${logfile} -d ${some_log_item}`,
error logs from error_report() and friends go to ${logfile}, but if QEMU
is started with `-daemonize -D ${logfile}` and no `-d`, the file isn't
even created and all logs go to /dev/null.

This inconsistency is quite confusing for users and gives the impression
that QEMU doesn't log errors at all. It seems much saner to always create
the log file when `-D` was passed and to be able to report errors.

It was spotted by the kata-containers project, which happens to do just
that `--daemonize -D` without `-d` trick.

v3:
- drop log_append (Paolo's patch)
- new approach : call qemu_log_trylock() from qemu_set_log_internal() in
  the per-thread case, instead of trying to special case the main thread

v2:
- new log_thread_id() implementation for hosts without gettid() syscall
- avoid conflict between global log file and per-thread logfile
- style improvements

Greg Kurz (1):
  util/log: Always send errors to logfile when daemonized

Paolo Bonzini (1):
  util/log: do not close and reopen log files when flags are turned off

 util/log.c | 84 +++++++++++++++++++++++++++++++++++++-----------------
 1 file changed, 58 insertions(+), 26 deletions(-)

-- 
2.38.1

[PATCH v3 1/2] util/log: do not close and reopen log files when flags are turned off

[Greg Kurz]

From: Paolo Bonzini <pbonzini@redhat.com>

log_append makes sure that if you turn off the logging (which clears
log_flags and makes need_to_open_file false) the old log is not
overwritten.  The usecase is that if you remove or move the file
QEMU will not keep writing to the old file.  However, this is
not always the desited behavior, in particular having log_append==1
after changing the file name makes little sense.

When qemu_set_log_internal is called from the logfile monitor
command, filename must be non-NULL and therefore changed_name must
be true.  Therefore, the only case where the file is closed and
need_to_open_file == false is indeed when log_flags becomes
zero.  In this case, just flush the file and do not bother
closing it, thus faking the same append behavior as previously.

The behavioral change is that changing the logfile twice, for
example log1 -> log2 -> log1, will cause log1 to be overwritten.
This can simply be documented, since it is not a particularly
surprising behavior.

Suggested-by: Alex Bennée <alex.bennee@linaro.org>
Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
Reviewed-by: Richard Henderson <richard.henderson@linaro.org>
Reviewed-by: Greg Kurz <groug@kaod.org>
Message-Id: <20221025092119.236224-1-pbonzini@redhat.com>
[groug: nullify global_file before actually closing the file]
Signed-off-by: Greg Kurz <groug@kaod.org>
---
 util/log.c | 14 ++++++--------
 1 file changed, 6 insertions(+), 8 deletions(-)

diff --git a/util/log.c b/util/log.c
index c2198badf240..fb843453dd49 100644
--- a/util/log.c
+++ b/util/log.c
@@ -45,7 +45,6 @@ static __thread FILE *thread_file;
 static __thread Notifier qemu_log_thread_cleanup_notifier;
 
 int qemu_loglevel;
-static bool log_append;
 static bool log_per_thread;
 static GArray *debug_regions;
 
@@ -277,19 +276,20 @@ static bool qemu_set_log_internal(const char *filename, bool changed_name,
     daemonized = is_daemonized();
     need_to_open_file = log_flags && !per_thread && (!daemonized || filename);
 
-    if (logfile && (!need_to_open_file || changed_name)) {
-        qatomic_rcu_set(&global_file, NULL);
-        if (logfile != stderr) {
+    if (logfile) {
+        fflush(logfile);
+        if (changed_name && logfile != stderr) {
             RCUCloseFILE *r = g_new0(RCUCloseFILE, 1);
             r->fd = logfile;
+            qatomic_rcu_set(&global_file, NULL);
             call_rcu(r, rcu_close_file, rcu);
+            logfile = NULL;
         }
-        logfile = NULL;
     }
 
     if (!logfile && need_to_open_file) {
         if (filename) {
-            logfile = fopen(filename, log_append ? "a" : "w");
+            logfile = fopen(filename, "w");
             if (!logfile) {
                 error_setg_errno(errp, errno, "Error opening logfile %s",
                                  filename);
@@ -308,8 +308,6 @@ static bool qemu_set_log_internal(const char *filename, bool changed_name,
             logfile = stderr;
         }
 
-        log_append = 1;
-
         qatomic_rcu_set(&global_file, logfile);
     }
     return true;
-- 
2.38.1

[PATCH v3 2/2] util/log: Always send errors to logfile when daemonized

[Greg Kurz]

When QEMU is started with `-daemonize`, all stdio descriptors get
redirected to `/dev/null`. This basically means that anything
printed with error_report() and friends is lost.

Current logging code allows to redirect to a file with `-D` but
this requires to enable some logging item with `-d` as well to
be functional.

Relax the check on the log flags when QEMU is daemonized, so that
other users of stderr can benefit from the redirection, without the
need to enable unwanted debug logs. Previous behaviour is retained
for the non-daemonized case. The logic is unrolled as an `if` for
better readability. The qemu_log_level and log_per_thread globals
reflect the state we want to transition to at this point : use
them instead of the intermediary locals for correctness.

qemu_set_log_internal() is adapted to open a per-thread log file
when '-d tid' is passed. This is done by hijacking qemu_try_lock()
which seems simpler that refactoring the code.

Signed-off-by: Greg Kurz <groug@kaod.org>
---
 util/log.c | 72 ++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 53 insertions(+), 19 deletions(-)

diff --git a/util/log.c b/util/log.c
index fb843453dd49..7837ff991769 100644
--- a/util/log.c
+++ b/util/log.c
@@ -79,13 +79,15 @@ static int log_thread_id(void)
 
 static void qemu_log_thread_cleanup(Notifier *n, void *unused)
 {
-    fclose(thread_file);
-    thread_file = NULL;
+    if (thread_file != stderr) {
+        fclose(thread_file);
+        thread_file = NULL;
+    }
 }
 
 /* Lock/unlock output. */
 
-FILE *qemu_log_trylock(void)
+static FILE *qemu_log_trylock_with_err(Error **errp)
 {
     FILE *logfile;
 
@@ -96,6 +98,9 @@ FILE *qemu_log_trylock(void)
                 = g_strdup_printf(global_filename, log_thread_id());
             logfile = fopen(filename, "w");
             if (!logfile) {
+                error_setg_errno(errp, errno,
+                                 "Error opening logfile %s for thread %d",
+                                 filename, log_thread_id());
                 return NULL;
             }
             thread_file = logfile;
@@ -122,6 +127,11 @@ FILE *qemu_log_trylock(void)
     return logfile;
 }
 
+FILE *qemu_log_trylock(void)
+{
+    return qemu_log_trylock_with_err(NULL);
+}
+
 void qemu_log_unlock(FILE *logfile)
 {
     if (logfile) {
@@ -265,16 +275,21 @@ static bool qemu_set_log_internal(const char *filename, bool changed_name,
 #endif
     qemu_loglevel = log_flags;
 
-    /*
-     * In all cases we only log if qemu_loglevel is set.
-     * Also:
-     *   If per-thread, open the file for each thread in qemu_log_lock.
-     *   If not daemonized we will always log either to stderr
-     *     or to a file (if there is a filename).
-     *   If we are daemonized, we will only log if there is a filename.
-     */
     daemonized = is_daemonized();
-    need_to_open_file = log_flags && !per_thread && (!daemonized || filename);
+    need_to_open_file = false;
+    if (!daemonized) {
+        /*
+         * If not daemonized we only log if qemu_loglevel is set, either to
+         * stderr or to a file (if there is a filename).
+         * If per-thread, open the file for each thread in qemu_log_trylock().
+         */
+        need_to_open_file = qemu_loglevel && !log_per_thread;
+    } else {
+        /*
+         * If we are daemonized, we will only log if there is a filename.
+         */
+        need_to_open_file = filename != NULL;
+    }
 
     if (logfile) {
         fflush(logfile);
@@ -287,19 +302,34 @@ static bool qemu_set_log_internal(const char *filename, bool changed_name,
         }
     }
 
+    if (log_per_thread && daemonized) {
+        logfile = thread_file;
+    }
+
     if (!logfile && need_to_open_file) {
         if (filename) {
-            logfile = fopen(filename, "w");
-            if (!logfile) {
-                error_setg_errno(errp, errno, "Error opening logfile %s",
-                                 filename);
-                return false;
+            if (log_per_thread) {
+                logfile = qemu_log_trylock_with_err(errp);
+                if (!logfile) {
+                    return false;
+                }
+                qemu_log_unlock(logfile);
+            } else {
+                logfile = fopen(filename, "w");
+                if (!logfile) {
+                    error_setg_errno(errp, errno, "Error opening logfile %s",
+                                     filename);
+                    return false;
+                }
             }
             /* In case we are a daemon redirect stderr to logfile */
             if (daemonized) {
                 dup2(fileno(logfile), STDERR_FILENO);
                 fclose(logfile);
-                /* This will skip closing logfile in rcu_close_file. */
+                /*
+                 * This will skip closing logfile in rcu_close_file()
+                 * or qemu_log_thread_cleanup().
+                 */
                 logfile = stderr;
             }
         } else {
@@ -308,7 +338,11 @@ static bool qemu_set_log_internal(const char *filename, bool changed_name,
             logfile = stderr;
         }
 
-        qatomic_rcu_set(&global_file, logfile);
+        if (log_per_thread && daemonized) {
+            thread_file = logfile;
+        } else {
+            qatomic_rcu_set(&global_file, logfile);
+        }
     }
     return true;
 }
-- 
2.38.1

Re: [PATCH v3 2/2] util/log: Always send errors to logfile when daemonized

[Richard Henderson]

On 11/9/22 01:00, Greg Kurz wrote:
> When QEMU is started with `-daemonize`, all stdio descriptors get
> redirected to `/dev/null`. This basically means that anything
> printed with error_report() and friends is lost.
> 
> Current logging code allows to redirect to a file with `-D` but
> this requires to enable some logging item with `-d` as well to
> be functional.
> 
> Relax the check on the log flags when QEMU is daemonized, so that
> other users of stderr can benefit from the redirection, without the
> need to enable unwanted debug logs. Previous behaviour is retained
> for the non-daemonized case. The logic is unrolled as an `if` for
> better readability. The qemu_log_level and log_per_thread globals
> reflect the state we want to transition to at this point : use
> them instead of the intermediary locals for correctness.
> 
> qemu_set_log_internal() is adapted to open a per-thread log file
> when '-d tid' is passed. This is done by hijacking qemu_try_lock()
> which seems simpler that refactoring the code.
> 
> Signed-off-by: Greg Kurz<groug@kaod.org>
> ---
>   util/log.c | 72 ++++++++++++++++++++++++++++++++++++++++--------------
>   1 file changed, 53 insertions(+), 19 deletions(-)

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

r~