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

[PATCH v2 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. It is possible that they will
stop doing so and catch errors through QEMU's stderr at some point, but
I'm posting the patches anyway.

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 (2):
  util/log: Derive thread id from getpid() on hosts w/o gettid() syscall
  util/log: Always send errors to logfile when daemonized

 util/log.c | 56 ++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 42 insertions(+), 14 deletions(-)

-- 
2.37.3

[PATCH v2 1/2] util/log: Derive thread id from getpid() on hosts w/o gettid() syscall

[Greg Kurz]

A subsequent patch needs to be able to differentiate the main QEMU
thread from other threads. An obvious way to do so is to compare
log_thread_id() and getpid(), based on the fact that they are equal
for the main thread on systems that have the gettid() syscall (e.g.
linux).

Adapt the fallback code for systems without gettid() to provide the
same assumption.

Suggested-by: Paolo Bonzini <pbonzini@redhat.com>
Signed-off-by: Greg Kurz <groug@kaod.org>
---
 util/log.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/util/log.c b/util/log.c
index d6eb0378c3a3..e1c2535cfcd2 100644
--- a/util/log.c
+++ b/util/log.c
@@ -72,8 +72,13 @@ static int log_thread_id(void)
 #elif defined(SYS_gettid)
     return syscall(SYS_gettid);
 #else
+    static __thread int my_id = -1;
     static int counter;
-    return qatomic_fetch_inc(&counter);
+
+    if (my_id == -1) {
+        my_id = getpid() + qatomic_fetch_inc(&counter);
+    }
+    return my_id;
 #endif
 }
 
-- 
2.37.3

Re: [PATCH v2 1/2] util/log: Derive thread id from getpid() on hosts w/o gettid() syscall

[Daniel P. Berrangé]

On Wed, Oct 19, 2022 at 05:16:50PM +0200, Greg Kurz wrote:
> A subsequent patch needs to be able to differentiate the main QEMU
> thread from other threads. An obvious way to do so is to compare
> log_thread_id() and getpid(), based on the fact that they are equal
> for the main thread on systems that have the gettid() syscall (e.g.
> linux).
> 
> Adapt the fallback code for systems without gettid() to provide the
> same assumption.
> 
> Suggested-by: Paolo Bonzini <pbonzini@redhat.com>
> Signed-off-by: Greg Kurz <groug@kaod.org>
> ---
>  util/log.c | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
> 
> diff --git a/util/log.c b/util/log.c
> index d6eb0378c3a3..e1c2535cfcd2 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -72,8 +72,13 @@ static int log_thread_id(void)
>  #elif defined(SYS_gettid)
>      return syscall(SYS_gettid);
>  #else
> +    static __thread int my_id = -1;
>      static int counter;
> -    return qatomic_fetch_inc(&counter);
> +
> +    if (my_id == -1) {
> +        my_id = getpid() + qatomic_fetch_inc(&counter);
> +    }
> +    return my_id;

This doesn't look safe for linux-user when we fork, but don't exec.

The getpid() will change after the fork, but counter won't be
reset, so a thread in the parent could clash with a thread
in the forked child.

I feel like if we want to check for the main thread, we should
be using pthread_self(), and compare result against the value
cached from main. Or cache in a __constructor__ function in
log.c to keep it isolated from main().


With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: [PATCH v2 1/2] util/log: Derive thread id from getpid() on hosts w/o gettid() syscall

[Greg Kurz]

On Wed, 19 Oct 2022 16:57:54 +0100
Daniel P. Berrangé <berrange@redhat.com> wrote:

> On Wed, Oct 19, 2022 at 05:16:50PM +0200, Greg Kurz wrote:
> > A subsequent patch needs to be able to differentiate the main QEMU
> > thread from other threads. An obvious way to do so is to compare
> > log_thread_id() and getpid(), based on the fact that they are equal
> > for the main thread on systems that have the gettid() syscall (e.g.
> > linux).
> > 
> > Adapt the fallback code for systems without gettid() to provide the
> > same assumption.
> > 
> > Suggested-by: Paolo Bonzini <pbonzini@redhat.com>
> > Signed-off-by: Greg Kurz <groug@kaod.org>
> > ---
> >  util/log.c | 7 ++++++-
> >  1 file changed, 6 insertions(+), 1 deletion(-)
> > 
> > diff --git a/util/log.c b/util/log.c
> > index d6eb0378c3a3..e1c2535cfcd2 100644
> > --- a/util/log.c
> > +++ b/util/log.c
> > @@ -72,8 +72,13 @@ static int log_thread_id(void)
> >  #elif defined(SYS_gettid)
> >      return syscall(SYS_gettid);
> >  #else
> > +    static __thread int my_id = -1;
> >      static int counter;
> > -    return qatomic_fetch_inc(&counter);
> > +
> > +    if (my_id == -1) {
> > +        my_id = getpid() + qatomic_fetch_inc(&counter);
> > +    }
> > +    return my_id;
> 
> This doesn't look safe for linux-user when we fork, but don't exec.
> 

... which is a "dangerous" situation if the parent is already
multi-threaded at fork() time. The child thread must only call
async-signal-safe functions and...


> The getpid() will change after the fork, but counter won't be
> reset, so a thread in the parent could clash with a thread
> in the forked child.
> 

... pthread_create() isn't one AFAIK. This case has undefined
behavior.

Anyway, no matter what we do, even with a regular fork+exec pattern,
log_thread_id() no longer guarantees unique values for all threads
that could be running concurrently (unlike gettid() or counter++),
e.g. 
- parent process with pid A and one extra thread
  => parent uses thread ids A and A+1
- fork child process with pid B == A+1
- child execs
  => child uses thread id A+1

> I feel like if we want to check for the main thread, we should
> be using pthread_self(), and compare result against the value
> cached from main. Or cache in a __constructor__ function in
> log.c to keep it isolated from main().
> 

Hmm... pthread_self() is only guaranteed to be unique within
a process. It doesn't look safe either to compare results
of pthread_self() from different process contexts.

> 
> With regards,
> Daniel

Thanks for bringing this corner case up ! It highlights that
I should definitely go for another approach that doesn't
require to check for the main thread at all.

Cheers,

--
Greg

Re: [PATCH v2 1/2] util/log: Derive thread id from getpid() on hosts w/o gettid() syscall

[Paolo Bonzini]

On 10/19/22 17:57, Daniel P. Berrangé wrote:
>> +    if (my_id == -1) {
>> +        my_id = getpid() + qatomic_fetch_inc(&counter);
>> +    }
>> +    return my_id;
> This doesn't look safe for linux-user when we fork, but don't exec.

Linux-user won't ever get here, however bsd-user might.  We should have 
get_thread_id() somewhere in util/, for example

https://github.com/wine-mirror/wine/blob/master/dlls/ntdll/unix/server.c

> The getpid() will change after the fork, but counter won't be
> reset, so a thread in the parent could clash with a thread
> in the forked child.

It might clash even if the counter is reset for that matter.

Paolo

Re: [PATCH v2 1/2] util/log: Derive thread id from getpid() on hosts w/o gettid() syscall

[Greg Kurz]

On Thu, 20 Oct 2022 12:39:41 +0200
Paolo Bonzini <pbonzini@redhat.com> wrote:

> On 10/19/22 17:57, Daniel P. Berrangé wrote:
> >> +    if (my_id == -1) {
> >> +        my_id = getpid() + qatomic_fetch_inc(&counter);
> >> +    }
> >> +    return my_id;
> > This doesn't look safe for linux-user when we fork, but don't exec.
> 
> Linux-user won't ever get here, however bsd-user might.  We should have 
> get_thread_id() somewhere in util/, for example
> 
> https://github.com/wine-mirror/wine/blob/master/dlls/ntdll/unix/server.c
> 

We have qemu_get_thread_id() already :

https://git.qemu.org/?p=qemu.git;a=blob;f=util/oslib-posix.c;h=827a7aadba444cdb128284f5b4ba43934c78c3db;hb=HEAD#l96

> > The getpid() will change after the fork, but counter won't be
> > reset, so a thread in the parent could clash with a thread
> > in the forked child.
> 
> It might clash even if the counter is reset for that matter.
> 

Yes.

> Paolo
> 

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

One could hope that passing `-D ${logfile}` would cause the messages
to go to `${logfile}`, as the documentation tends to suggest:

      -D logfile
              Output log in logfile instead of to stderr

Unfortunately, `-D` belongs to the logging framework and it only
does this redirection if some log item is also enabled with `-d`
or if QEMU was configured with `--enable-trace-backend=log`. A
typical production setup doesn't do tracing or fine-grain
debugging but it certainly needs to collect errors.

Ignore the check on enabled log items when QEMU is daemonized. Previous
behaviour is retained for the non-daemonized case. The logic is unrolled
as an `if` for better readability. Since qemu_set_log_internal() caches
the final log level and the per-thread property in global variables, it
seems more correct to check these instead of intermediary local variables.

Special care is needed for the `-D ${logfile} -d tid` case : `${logfile}`
is expected to be a template that contains exactly one `%d` that should be
expanded to a PID or TID. The logic in qemu_log_trylock() already takes
care of that for per-thread logs. Do it as well for the QEMU main thread
when opening the file.

Note that qemu_log_trylock() now must ensure that the main QEMU thread
only uses the global log file ; qemu_log_unlock() must be adapted as well
by checking thread_file which is always equal to NULL for the main thread.

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

diff --git a/util/log.c b/util/log.c
index e1c2535cfcd2..0fa23729c78c 100644
--- a/util/log.c
+++ b/util/log.c
@@ -82,6 +82,11 @@ static int log_thread_id(void)
 #endif
 }
 
+static bool is_main_log_thread(void)
+{
+    return log_thread_id() == getpid();
+}
+
 /* Lock/unlock output. */
 
 FILE *qemu_log_trylock(void)
@@ -90,7 +95,8 @@ FILE *qemu_log_trylock(void)
 
     logfile = thread_file;
     if (!logfile) {
-        if (log_per_thread) {
+        /* Main thread to use the global file only */
+        if (log_per_thread && !is_main_log_thread()) {
             g_autofree char *filename
                 = g_strdup_printf(global_filename, log_thread_id());
             logfile = fopen(filename, "w");
@@ -124,7 +130,7 @@ void qemu_log_unlock(FILE *logfile)
     if (logfile) {
         fflush(logfile);
         qemu_funlockfile(logfile);
-        if (!log_per_thread) {
+        if (!thread_file) {
             rcu_read_unlock();
         }
     }
@@ -253,16 +259,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 && (!need_to_open_file || changed_name)) {
         qatomic_rcu_set(&global_file, NULL);
@@ -276,10 +287,22 @@ static bool qemu_set_log_internal(const char *filename, bool changed_name,
 
     if (!logfile && need_to_open_file) {
         if (filename) {
-            logfile = fopen(filename, log_append ? "a" : "w");
+            g_autofree char *fname = NULL;
+
+            /*
+             * If per-thread, filename contains a single %d that should be
+             * converted.
+             */
+            if (per_thread) {
+                fname = g_strdup_printf(filename, getpid());
+            } else {
+                fname = g_strdup(filename);
+            }
+
+            logfile = fopen(fname, log_append ? "a" : "w");
             if (!logfile) {
                 error_setg_errno(errp, errno, "Error opening logfile %s",
-                                 filename);
+                                 fname);
                 return false;
             }
             /* In case we are a daemon redirect stderr to logfile */
-- 
2.37.3

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

[Richard Henderson]

On 10/20/22 01:16, 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.
> 
> One could hope that passing `-D ${logfile}` would cause the messages
> to go to `${logfile}`, as the documentation tends to suggest:
> 
>        -D logfile
>                Output log in logfile instead of to stderr
> 
> Unfortunately, `-D` belongs to the logging framework and it only
> does this redirection if some log item is also enabled with `-d`
> or if QEMU was configured with `--enable-trace-backend=log`. A
> typical production setup doesn't do tracing or fine-grain
> debugging but it certainly needs to collect errors.
> 
> Ignore the check on enabled log items when QEMU is daemonized. Previous
> behaviour is retained for the non-daemonized case. The logic is unrolled
> as an `if` for better readability. Since qemu_set_log_internal() caches
> the final log level and the per-thread property in global variables, it
> seems more correct to check these instead of intermediary local variables.
> 
> Special care is needed for the `-D ${logfile} -d tid` case : `${logfile}`
> is expected to be a template that contains exactly one `%d` that should be
> expanded to a PID or TID. The logic in qemu_log_trylock() already takes
> care of that for per-thread logs. Do it as well for the QEMU main thread
> when opening the file.

I don't understand why daemonize changes -d tid at all.
If there's a bug there, please separate it out.

I don't understand the is_main_log_thread checks.
Why is the main thread special?

> -    /*
> -     * 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;
> +    }

I would have thought that this was the only change required -- ignoring qemu_loglevel when 
daemonized.


r~

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

[Greg Kurz]

On Thu, 20 Oct 2022 12:21:27 +1000
Richard Henderson <richard.henderson@linaro.org> wrote:

> On 10/20/22 01:16, 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.
> > 
> > One could hope that passing `-D ${logfile}` would cause the messages
> > to go to `${logfile}`, as the documentation tends to suggest:
> > 
> >        -D logfile
> >                Output log in logfile instead of to stderr
> > 
> > Unfortunately, `-D` belongs to the logging framework and it only
> > does this redirection if some log item is also enabled with `-d`
> > or if QEMU was configured with `--enable-trace-backend=log`. A
> > typical production setup doesn't do tracing or fine-grain
> > debugging but it certainly needs to collect errors.
> > 
> > Ignore the check on enabled log items when QEMU is daemonized. Previous
> > behaviour is retained for the non-daemonized case. The logic is unrolled
> > as an `if` for better readability. Since qemu_set_log_internal() caches
> > the final log level and the per-thread property in global variables, it
> > seems more correct to check these instead of intermediary local variables.
> > 
> > Special care is needed for the `-D ${logfile} -d tid` case : `${logfile}`
> > is expected to be a template that contains exactly one `%d` that should be
> > expanded to a PID or TID. The logic in qemu_log_trylock() already takes
> > care of that for per-thread logs. Do it as well for the QEMU main thread
> > when opening the file.
> 
> I don't understand why daemonize changes -d tid at all.
> If there's a bug there, please separate it out.
> 
> I don't understand the is_main_log_thread checks.
> Why is the main thread special?
> 

The current code base either opens a per-thread file in
qemu_log_trylock() when -d tid is enabled, or only a
single global file in qemu_log_set_internal() in the
opposite case.

The goal of this patch is to go through the `In case we
are a daemon redirect stderr to logfile` logic, so that
other users of stderr, aka. error_report(), can benefit
from it as well. Since this is only done for the global
file, the logic was changed to : _main_ thread to always
use the global file and other threads to use the per-thread
file.

I now realize how terrible a choice this is. It violates
the current logic too much and brings new problems like
"how to identify the main thread"...

> > -    /*
> > -     * 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;
> > +    }
> 
> I would have thought that this was the only change required -- ignoring qemu_loglevel when 
> daemonized.
> 

I was thinking the same at first, but this ended up in the
global file being open with a filename containing a '%d'...
I chose the direction of doing the g_strdup_printf() trick
for the global file as well but then I had to make sure
that qemu_log_trylock() wouldn't try later to open the same
file, hence the _main_ thread check...

The question is actually : where stderr should point to in
the '-daemonize -D foo%d.log -d tid` case ?

> 

> r~

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

[Daniel P. Berrangé]

On Thu, Oct 20, 2022 at 11:49:37AM +0200, Greg Kurz wrote:
> On Thu, 20 Oct 2022 12:21:27 +1000
> Richard Henderson <richard.henderson@linaro.org> wrote:
> 
> > On 10/20/22 01:16, Greg Kurz wrote:
> > 
> > I don't understand why daemonize changes -d tid at all.
> > If there's a bug there, please separate it out.
> > 
> > I don't understand the is_main_log_thread checks.
> > Why is the main thread special?
> > 
> 
> The current code base either opens a per-thread file in
> qemu_log_trylock() when -d tid is enabled, or only a
> single global file in qemu_log_set_internal() in the
> opposite case.
> 
> The goal of this patch is to go through the `In case we
> are a daemon redirect stderr to logfile` logic, so that
> other users of stderr, aka. error_report(), can benefit
> from it as well. Since this is only done for the global
> file, the logic was changed to : _main_ thread to always
> use the global file and other threads to use the per-thread
> file.
> 
> I now realize how terrible a choice this is. It violates
> the current logic too much and brings new problems like
> "how to identify the main thread"...

snip

> > I would have thought that this was the only change required -- ignoring qemu_loglevel when 
> > daemonized.
> > 
> 
> I was thinking the same at first, but this ended up in the
> global file being open with a filename containing a '%d'...
> I chose the direction of doing the g_strdup_printf() trick
> for the global file as well but then I had to make sure
> that qemu_log_trylock() wouldn't try later to open the same
> file, hence the _main_ thread check...
> 
> The question is actually : where stderr should point to in
> the '-daemonize -D foo%d.log -d tid` case ?

I'm tending towards thinking the question is wrong, because
it is imposing semantics on -D that it was never designed to
address.

The '-d' option enables logging in QEMU, primary for things
related to TCG. By default that logging goes to stderr, but
it can be sent to 1 or mnay files, using -D. IOW, -D is NOT
about controlling where stderr/out is connected. It is
about where TCG logging goes.


Separately, IIUC, you found that when using -daemonize any
error_report() messages end up in the void, because stderr
is connected to /dev/null.

This patch is thus attempting to repurpose -D as a way to
say where error_report() messages end up with daemonized,
and this creates the complexity  because -D was never
intended to be a mechanism to control stderr or error_report
output.

If we want to connect stdout/err to something when daemonized
then lets either have a dedicated option for that, or simply
tell apps not to use -daemonize and to take care of daemonzing
themselves, thus having full control over stdout/err. The latter
is what libvirt uses, because we actually want stderr/out on a
pipe, not a file, in order to enforce rollover.

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

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

[Paolo Bonzini]

On 10/20/22 11:58, Daniel P. Berrangé wrote:
> 
> The '-d' option enables logging in QEMU, primary for things
> related to TCG. By default that logging goes to stderr, but
> it can be sent to 1 or mnay files, using -D. IOW, -D is NOT
> about controlling where stderr/out is connected. It is
> about where TCG logging goes.

(Aside: it's not just TCG logging.  The default tracing backend is also 
printing to -D).

> Separately, IIUC, you found that when using -daemonize any
> error_report() messages end up in the void, because stderr
> is connected to /dev/null.
> 
> This patch is thus attempting to repurpose -D as a way to
> say where error_report() messages end up with daemonized,
> and this creates the complexity  because -D was never
> intended to be a mechanism to control stderr or error_report
> output.

True, but it already does that if "-d" is specified, because "-d" 
*intentionally* reopens stderr when -daemonize is specified.  So I think 
overall the idea of "make -D always open the destination when 
daemonizing" is sound, the only weird thing is the interaction with "-d 
tid" which is fixed if we just replace the fallback case from 
log_thread_id() as in Wine's get_unix_tid() code.  "-d tid" can just be 
forbidden if the platform is not supported by get_unix_tid().

> If we want to connect stdout/err to something when daemonized
> then lets either have a dedicated option for that, or simply
> tell apps not to use -daemonize and to take care of daemonzing
> themselves, thus having full control over stdout/err. The latter
> is what libvirt uses, because we actually want stderr/out on a
> pipe, not a file, in order to enforce rollover.

I would gladly get rid of -daemonize, unfortunately it has many users. 
Adding further complication to it is not beautiful, but overall I think 
Greg's patch does make sense.  In particular I would continue the 
refactoring by moving


             /*
              * If per-thread, filename contains a single %d that should be
              * converted.
              */
             if (per_thread) {
                 fname = g_strdup_printf(filename, getpid());
             } else {
                 fname = g_strdup(filename);
             }

             return fopen(fname, log_append ? "a" : "w");

to a new function that can be used in both qemu_log_trylock() and 
qemu_set_log_internal().  (In fact this refactoring is a bugfix because 
per-thread log files do not currently obey log_append).

Paolo

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

[Alex Bennée]

Paolo Bonzini <pbonzini@redhat.com> writes:

<snip>
>> If we want to connect stdout/err to something when daemonized
>> then lets either have a dedicated option for that, or simply
>> tell apps not to use -daemonize and to take care of daemonzing
>> themselves, thus having full control over stdout/err. The latter
>> is what libvirt uses, because we actually want stderr/out on a
>> pipe, not a file, in order to enforce rollover.
>
> I would gladly get rid of -daemonize, unfortunately it has many users.
> Adding further complication to it is not beautiful, but overall I
> think Greg's patch does make sense.  In particular I would continue
> the refactoring by moving
>
>
>             /*
>              * If per-thread, filename contains a single %d that should be
>              * converted.
>              */
>             if (per_thread) {
>                 fname = g_strdup_printf(filename, getpid());
>             } else {
>                 fname = g_strdup(filename);
>             }
>
>             return fopen(fname, log_append ? "a" : "w");
>
> to a new function that can be used in both qemu_log_trylock() and
> qemu_set_log_internal().  (In fact this refactoring is a bugfix
> because per-thread log files do not currently obey log_append).

What is the use case for log_append. AFAICT it only ever applied if you
did a dynamic set_log. Was it ever really used or should it be dropped
as an excessive complication?

From my point of view appending to an existing per-thread log is just
going to cause confusion.

>
> Paolo


-- 
Alex Bennée

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

[Greg Kurz]

On Mon, 24 Oct 2022 10:44:11 +0100
Alex Bennée <alex.bennee@linaro.org> wrote:

> 
> Paolo Bonzini <pbonzini@redhat.com> writes:
> 
> <snip>
> >> If we want to connect stdout/err to something when daemonized
> >> then lets either have a dedicated option for that, or simply
> >> tell apps not to use -daemonize and to take care of daemonzing
> >> themselves, thus having full control over stdout/err. The latter
> >> is what libvirt uses, because we actually want stderr/out on a
> >> pipe, not a file, in order to enforce rollover.
> >
> > I would gladly get rid of -daemonize, unfortunately it has many users.
> > Adding further complication to it is not beautiful, but overall I
> > think Greg's patch does make sense.  In particular I would continue
> > the refactoring by moving
> >
> >
> >             /*
> >              * If per-thread, filename contains a single %d that should be
> >              * converted.
> >              */
> >             if (per_thread) {
> >                 fname = g_strdup_printf(filename, getpid());
> >             } else {
> >                 fname = g_strdup(filename);
> >             }
> >
> >             return fopen(fname, log_append ? "a" : "w");
> >
> > to a new function that can be used in both qemu_log_trylock() and
> > qemu_set_log_internal().  (In fact this refactoring is a bugfix
> > because per-thread log files do not currently obey log_append).
> 
> What is the use case for log_append. AFAICT it only ever applied if you
> did a dynamic set_log. Was it ever really used or should it be dropped
> as an excessive complication?
> 

The use case seems to be able to temporarily disable logging,
which closes the log file, without loosing already logged stuff
when logging is re-enabled. QEMU not overwriting previous logs
from the same run is certainly a legitimate expectation from the
user.

Complexity mostly stems from the fact that the log file gets closed
when doing `log none` from the monitor. The logic is also a bit
inconsistent : initial open ensures that we go with a pristine log
file, but renaming the file from the monitor will gladly append
messages to a pre-existing unrelated file...

> From my point of view appending to an existing per-thread log is just
> going to cause confusion.
> 

... and cause confusion all the same.

I'd rather leave the log file always open, except on renames,
and always open in truncating mode.

> >
> > Paolo
> 
> 

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

[Paolo Bonzini]

On 10/24/22 11:44, Alex Bennée wrote:
> 
> Paolo Bonzini <pbonzini@redhat.com> writes:
> 
> <snip>
>>> If we want to connect stdout/err to something when daemonized
>>> then lets either have a dedicated option for that, or simply
>>> tell apps not to use -daemonize and to take care of daemonzing
>>> themselves, thus having full control over stdout/err. The latter
>>> is what libvirt uses, because we actually want stderr/out on a
>>> pipe, not a file, in order to enforce rollover.
>>
>> I would gladly get rid of -daemonize, unfortunately it has many users.
>> Adding further complication to it is not beautiful, but overall I
>> think Greg's patch does make sense.  In particular I would continue
>> the refactoring by moving
>>
>>
>>              /*
>>               * If per-thread, filename contains a single %d that should be
>>               * converted.
>>               */
>>              if (per_thread) {
>>                  fname = g_strdup_printf(filename, getpid());
>>              } else {
>>                  fname = g_strdup(filename);
>>              }
>>
>>              return fopen(fname, log_append ? "a" : "w");
>>
>> to a new function that can be used in both qemu_log_trylock() and
>> qemu_set_log_internal().  (In fact this refactoring is a bugfix
>> because per-thread log files do not currently obey log_append).
> 
> What is the use case for log_append. AFAICT it only ever applied if you
> did a dynamic set_log. Was it ever really used or should it be dropped
> as an excessive complication?

log_append is used if you turn off the logging, which clears log_flags, 
and then turn it on again.  The usecase is that if you remove the file 
QEMU won't keep writing to a deleted file.  ¯\_(ツ)_/¯

However, it's messy.  In particular after changing the file name 
log_append will be 1 and that makes little sense.  The simplest thing to 
do here is just to not close the file, I sent a patch for that.

Paolo

>  From my point of view appending to an existing per-thread log is just
> going to cause confusion.
> 
>>
>> Paolo
> 
>