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.3On 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 -- |: 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 :|
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
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
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
>
>
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 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
© 2016 - 2026 Red Hat, Inc.