Currently the tracing 'log' back emits special code to add timestamps
to trace points sent via qemu_log(). This current impl is a bad design
for a number of reasons.
* It changes the QEMU headers, such that 'error-report.h' content
is visible to all files using tracing, but only when the 'log'
backend is enabled. This has led to build failure bugs as devs
rarely test without the (default) 'log' backend enabled, and
CI can't cover every scenario for every trace backend.
* It bloats the trace points definitions which are inlined into
every probe location due to repeated inlining of timestamp
formatting code, adding MBs of overhead to QEMU.
* The tracing subsystem should not be treated any differently
from other users of qemu_log. They all would benefit from
having timestamps present.
* The timestamp emitted with the tracepoints is in a needlessly
different format to that used by error_report() in response
to '-msg timestamp=on'.
This fixes all these issues simply by moving timestamp formatting
into qemu_log, using the same approach as for error_report.
The code before:
static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
{
if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
if (message_with_timestamp) {
struct timeval _now;
gettimeofday(&_now, NULL);
qemu_log("%d@%zu.%06zu:qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n",
qemu_get_thread_id(),
(size_t)_now.tv_sec, (size_t)_now.tv_usec
, creds, filename, path);
} else {
qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
}
}
}
and after:
static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
{
if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
}
}
The log and error messages before:
$ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
2986097@1753122905.917608:qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55d925bd9490 dir=/var/home/berrange/tls
2986097@1753122905.917621:qcrypto_tls_creds_get_path TLS creds path creds=0x55d925bd9490 filename=ca-cert.pem path=<none>
2025-07-21T18:35:05.917626Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
and after:
$ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
2025-07-21T18:43:28.089797Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55bf5bf12380 dir=/var/home/berrange/tls
2025-07-21T18:43:28.089815Z qcrypto_tls_creds_get_path TLS creds path creds=0x55bf5bf12380 filename=ca-cert.pem path=<none>
2025-07-21T18:43:28.089819Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
The binary size before:
$ ls -alh qemu-system-x86_64
-rwxr-xr-x. 1 berrange berrange 87M Jul 21 19:39 qemu-system-x86_64
$ strip qemu-system-x86_64
$ ls -alh qemu-system-x86_64
-rwxr-xr-x. 1 berrange berrange 30M Jul 21 19:39 qemu-system-x86_64
and after:
$ ls -alh qemu-system-x86_64
-rwxr-xr-x. 1 berrange berrange 85M Jul 21 19:41 qemu-system-x86_64
$ strip qemu-system-x86_64
$ ls -alh qemu-system-x86_64
-rwxr-xr-x. 1 berrange berrange 29M Jul 21 19:41 qemu-system-x86_64
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Reviewed-by: Markus Armbruster <armbru@redhat.com>
Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
Message-id: 20250721185452.3016488-1-berrange@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
This makes it possible to lock the log file; it also makes log_mask_ln!
not allocate memory when logging a constant string.
Reviewed-by: Zhao Liu <zhao1.liu@intel.com>
Reviewed-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
Currently -d guest_errors enables logging of different invalid actions
by the guest such as misusing hardware, accessing missing features or
invalid memory areas. The memory access logging can be quite verbose
which obscures the other messages enabled by this debug switch so
separate it by adding a new -d invalid_mem option to make it possible
to control it independently of other guest error logs.
Signed-off-by: BALATON Zoltan <balaton@eik.bme.hu>
Reviewed-by: Peter Maydell <peter.maydell@linaro.org>
Message-ID: <1bb0d0e91ba14aca13056df3b0a774f89cbf966c.1730549443.git.balaton@eik.bme.hu>
Signed-off-by: Philippe Mathieu-Daudé <philmd@linaro.org>
The DEBUG_PLUGIN_GEN_OPS ifdef is replaced with "-d op_plugin".
The second pr_ops call can be obtained with "-d op".
Reviewed-by: Pierrick Bouvier <pierrick.bouvier@linaro.org>
Signed-off-by: Richard Henderson <richard.henderson@linaro.org>
Commit 59bde21374 ("util/log: do not close and reopen log files when
flags are turned off") prevented switching away from stderr on a
subsequent invocation of qemu_set_log_internal(). This prevented
switching away from stderr with the 'logfile' monitor command as well
as an invocation like
> ./qemu-system-x86_64 -trace 'qemu_mutex_lock,file=log'
from opening the specified log file.
Fixes: 59bde21374 ("util/log: do not close and reopen log files when flags are turned off")
Signed-off-by: Fiona Ebner <f.ebner@proxmox.com>
Message-ID: <20231004124446.491481-1-f.ebner@proxmox.com>
Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
The help text of the -d plugin option has a new line at the end which
is not needed as one is added automatically. Fixing it removes the
unexpected empty line in -d help output.
Signed-off-by: BALATON Zoltan <balaton@eik.bme.hu>
Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
Message-Id: <20230119214033.600FB74645F@zero.eik.bme.hu>
Signed-off-by: Philippe Mathieu-Daudé <philmd@linaro.org>
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>
Message-Id: <20221108140032.1460307-3-groug@kaod.org>
Signed-off-by: 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>
Message-Id: <20221108140032.1460307-2-groug@kaod.org>
Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
If QEMU is started with `-D qemu.log.%d` without any `-d` option,
doing `log all` in the monitor fails with:
Filename template with '%d' required for 'tid'
It is confusing since '%d' was actually passed.
This happens because QEMU caches the log file name with %d converted
to getpid() since `tid` wasn't required. This name isn't suitable
for a subsequent enablement of per-thread logs. There's little cause
to change the behavior as `-d tid` is mostly used at user-only startup.
Drop the per-thread from the requested flags in this case : `log all`
will thus enable everything except `tid` instead of failing. This is
preferable over forcing the user to enable each log item individually.
With this patch, `tid` is now truely immutable : it can only be set
or unset from the command line and never changed afterwards.
Fixes: 4e51069d67 ("util/log: Support per-thread log files")
Cc: richard.henderson@linaro.org
Signed-off-by: Greg Kurz <groug@kaod.org>
Reviewed-by: Richard Henderson <richard.henderson@linaro.org>
Message-id: 20221104120059.678470-3-groug@kaod.org
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Per-thread logging was implemented under the assumption that once
enabled, it is not possible to switch back to single file logging.
This isn't enforced though and it is possible to go through the
global file opening sequence in per-thread mode. The code isn't
ready for this and produces unexpected results as detailed below.
Start QEMU in system emulation mode with `-D ./qemu.log.%d -d tid`
and then change the log level from the monitor to something that
doesn't have tid, e.g. `log cpu_reset`. The value of log_flags
is zero and per_thread is set to false : the rest of the code
then assumes it is running in the global log case and opens a
file named `qemu.log.%d`, which is obviously not an expected
behavior.
Enforce the immutability of the flag early in qemu_set_log_internal()
so that its value is correct for all subsequent users.
Fixes: 4e51069d67 ("util/log: Support per-thread log files")
Cc: richard.henderson@linaro.org
Signed-off-by: Greg Kurz <groug@kaod.org>
Reviewed-by: Richard Henderson <richard.henderson@linaro.org>
Message-id: 20221104120059.678470-2-groug@kaod.org
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
When `-D ${logfile} -d tid` is passed, qemu_log_trylock() creates
a dedicated log file for the current thread and opens it. The
corresponding file descriptor is cached in a __thread variable.
Nothing is done to close the corresponding file descriptor when the
thread terminates though and the file descriptor is leaked.
The issue was found during code inspection and reproduced manually.
Fix that with an atexit notifier.
Fixes: 4e51069d67 ("util/log: Support per-thread log files")
Cc: richard.henderson@linaro.org
Signed-off-by: Greg Kurz <groug@kaod.org>
Message-Id: <20221021105734.555797-1-groug@kaod.org>
Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
Add a new log flag, tid, to turn this feature on.
Require the log filename to be set, and to contain %d.
Do not allow tid to be turned off once it is on, nor let
the filename be change thereafter. This avoids the need
for signalling each thread to re-open on a name change.
Reviewed-by: Alex Bennée <alex.bennee@linaro.org>
Signed-off-by: Richard Henderson <richard.henderson@linaro.org>
Message-Id: <20220417183019.755276-40-richard.henderson@linaro.org>
Use FILE* for global_file. We can perform an rcu_read on that
just as easily as RCUCloseFILE*. This simplifies a couple of
places, where previously we required taking the rcu_read_lock
simply to avoid racing to dereference RCUCloseFile->fd.
Only allocate the RCUCloseFile prior to call_rcu.
Reviewed-by: Alex Bennée <alex.bennee@linaro.org>
Signed-off-by: Richard Henderson <richard.henderson@linaro.org>
Message-Id: <20220417183019.755276-39-richard.henderson@linaro.org>
The only real use is in cpu_abort, where we have just
flushed the file via qemu_log_unlock, and are just about
to force-crash the application via abort. We do not
really need to close the FILE before the abort.
The two uses in test-logging.c can be handled with
qemu_set_log_filename_flags.
Reviewed-by: Alex Bennée <alex.bennee@linaro.org>
Signed-off-by: Richard Henderson <richard.henderson@linaro.org>
Message-Id: <20220417183019.755276-32-richard.henderson@linaro.org>
Daniel P. BerrangéandStefan Hajnoczi
Paolo Bonzini
BALATON ZoltanandPhilippe Mathieu-Daudé
Richard Henderson
Fiona EbnerandPaolo Bonzini
Ivan KlokovandAlistair Francis
Greg KurzandPaolo Bonzini