| Message ID | 20221019151651.334334-3-groug@kaod.org |
|---|---|
| State | New |
| Headers | show |
| Series | util/log: Always send errors to logfile when daemonized | expand |
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~
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~
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
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
On Thu, 20 Oct 2022 12:52:21 +0200 Paolo Bonzini <pbonzini@redhat.com> wrote: > 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. > I agree about the semantics of -D but the implementation forces the logging to go through stderr connected to a file in the daemonize case... so in the end -D controls where stderr is connected to, and this affects any other non-log user of stderr. > (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, This is exactly why I decided to try this approach. > 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(). > static int get_unix_tid(void) { int ret = -1; #ifdef HAVE_PTHREAD_GETTHREADID_NP ret = pthread_getthreadid_np(); #elif defined(linux) ret = syscall( __NR_gettid ); #elif defined(__sun) ret = pthread_self(); #elif defined(__APPLE__) ret = mach_thread_self(); mach_port_deallocate(mach_task_self(), ret); #elif defined(__NetBSD__) ret = _lwp_self(); #elif defined(__FreeBSD__) long lwpid; thr_self( &lwpid ); ret = lwpid; #elif defined(__DragonFly__) ret = lwp_gettid(); #endif return ret; } We could import all these cases except the defined(linux) case maybe since it should be covered by what we already have in log_thread_id() : #ifdef CONFIG_GETTID return gettid(); #elif defined(SYS_gettid) return syscall(SYS_gettid); > > 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"); > +1 > 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). > I had missed that but yes indeed... I'll fix that in a preparatory patch. > Paolo > Thanks Paolo ! -- Greg
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
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 > >
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 > >
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 */
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(-)