qemu/util/log.c

Ignoring revisions in .git-blame-ignore-revs. Click here to bypass and see the normal blame view.

553 lines
15 KiB
C
Raw Normal View History

/*
* Logging support
*
* Copyright (c) 2003 Fabrice Bellard
*
* This library is free software; you can redistribute it and/or
* modify it under the terms of the GNU Lesser General Public
* License as published by the Free Software Foundation; either
* version 2.1 of the License, or (at your option) any later version.
*
* This library is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
* Lesser General Public License for more details.
*
* You should have received a copy of the GNU Lesser General Public
* License along with this library; if not, see <http://www.gnu.org/licenses/>.
*/
#include "qemu/osdep.h"
#include "qemu/log.h"
#include "qemu/range.h"
#include "qemu/error-report.h"
#include "qapi/error.h"
#include "qemu/cutils.h"
#include "trace/control.h"
#include "qemu/thread.h"
#include "qemu/lockable.h"
#include "qemu/rcu.h"
#ifdef CONFIG_LINUX
#include <sys/syscall.h>
#endif
typedef struct RCUCloseFILE {
struct rcu_head rcu;
FILE *fd;
} RCUCloseFILE;
/* Mutex covering the other global_* variables. */
static QemuMutex global_mutex;
static char *global_filename;
static FILE *global_file;
static __thread FILE *thread_file;
static __thread Notifier qemu_log_thread_cleanup_notifier;
int qemu_loglevel;
static bool log_per_thread;
static GArray *debug_regions;
/* Returns true if qemu_log() will really write somewhere. */
bool qemu_log_enabled(void)
{
return log_per_thread || qatomic_read(&global_file) != NULL;
}
/* Returns true if qemu_log() will write somewhere other than stderr. */
bool qemu_log_separate(void)
{
if (log_per_thread) {
return true;
} else {
FILE *logfile = qatomic_read(&global_file);
return logfile && logfile != stderr;
}
}
static int log_thread_id(void)
{
#ifdef CONFIG_GETTID
return gettid();
#elif defined(SYS_gettid)
return syscall(SYS_gettid);
#else
static int counter;
return qatomic_fetch_inc(&counter);
#endif
}
static void qemu_log_thread_cleanup(Notifier *n, void *unused)
{
if (thread_file != stderr) {
fclose(thread_file);
thread_file = NULL;
}
}
/* Lock/unlock output. */
static FILE *qemu_log_trylock_with_err(Error **errp)
{
FILE *logfile;
logfile = thread_file;
if (!logfile) {
if (log_per_thread) {
g_autofree char *filename
= g_strdup_printf(global_filename, log_thread_id());
logfile = fopen(filename, "w");
if (!logfile) {
error_setg_errno(errp, errno,
"Error opening logfile %s for thread %d",
filename, log_thread_id());
return NULL;
}
thread_file = logfile;
qemu_log_thread_cleanup_notifier.notify = qemu_log_thread_cleanup;
qemu_thread_atexit_add(&qemu_log_thread_cleanup_notifier);
} else {
rcu_read_lock();
/*
* FIXME: typeof_strip_qual, as used by qatomic_rcu_read,
* does not work with pointers to undefined structures,
* such as we have with struct _IO_FILE and musl libc.
* Since all we want is a read of a pointer, cast to void**,
* which does work with typeof_strip_qual.
*/
logfile = qatomic_rcu_read((void **)&global_file);
if (!logfile) {
rcu_read_unlock();
return NULL;
}
}
}
qemu_flockfile(logfile);
return logfile;
}
FILE *qemu_log_trylock(void)
{
return qemu_log_trylock_with_err(NULL);
}
void qemu_log_unlock(FILE *logfile)
{
if (logfile) {
fflush(logfile);
qemu_funlockfile(logfile);
if (!log_per_thread) {
rcu_read_unlock();
}
}
}
void qemu_log(const char *fmt, ...)
{
FILE *f = qemu_log_trylock();
if (f) {
va_list ap;
va_start(ap, fmt);
vfprintf(f, fmt, ap);
va_end(ap);
qemu_log_unlock(f);
}
}
static void __attribute__((__constructor__)) startup(void)
{
qemu_mutex_init(&global_mutex);
}
static void rcu_close_file(RCUCloseFILE *r)
{
fclose(r->fd);
g_free(r);
}
/**
* valid_filename_template:
*
* Validate the filename template. Require %d if per_thread, allow it
* otherwise; require no other % within the template.
*/
typedef enum {
vft_error,
vft_stderr,
vft_strdup,
vft_pid_printf,
} ValidFilenameTemplateResult;
static ValidFilenameTemplateResult
valid_filename_template(const char *filename, bool per_thread, Error **errp)
{
if (filename) {
char *pidstr = strstr(filename, "%");
if (pidstr) {
/* We only accept one %d, no other format strings */
if (pidstr[1] != 'd' || strchr(pidstr + 2, '%')) {
error_setg(errp, "Bad logfile template: %s", filename);
return 0;
}
return per_thread ? vft_strdup : vft_pid_printf;
}
}
if (per_thread) {
error_setg(errp, "Filename template with '%%d' required for 'tid'");
return vft_error;
}
return filename ? vft_strdup : vft_stderr;
}
/* enable or disable low levels log */
static bool qemu_set_log_internal(const char *filename, bool changed_name,
int log_flags, Error **errp)
{
bool need_to_open_file;
bool daemonized;
bool per_thread;
FILE *logfile;
QEMU_LOCK_GUARD(&global_mutex);
logfile = global_file;
/* The per-thread flag is immutable. */
if (log_per_thread) {
log_flags |= LOG_PER_THREAD;
} else {
if (global_filename) {
log_flags &= ~LOG_PER_THREAD;
}
}
per_thread = log_flags & LOG_PER_THREAD;
if (changed_name) {
char *newname = NULL;
/*
* Once threads start opening their own log files, we have no
* easy mechanism to tell them all to close and re-open.
* There seems little cause to do so either -- this option
* will most often be used at user-only startup.
*/
if (log_per_thread) {
error_setg(errp, "Cannot change log filename after setting 'tid'");
return false;
}
switch (valid_filename_template(filename, per_thread, errp)) {
case vft_error:
return false;
case vft_stderr:
break;
case vft_strdup:
newname = g_strdup(filename);
break;
case vft_pid_printf:
newname = g_strdup_printf(filename, getpid());
break;
}
g_free(global_filename);
global_filename = newname;
filename = newname;
} else {
filename = global_filename;
if (per_thread &&
valid_filename_template(filename, true, errp) == vft_error) {
return false;
}
}
/* Once the per-thread flag is set, it cannot be unset. */
if (per_thread) {
log_per_thread = true;
}
/* The flag itself is not relevant for need_to_open_file. */
log_flags &= ~LOG_PER_THREAD;
#ifdef CONFIG_TRACE_LOG
log_flags |= LOG_TRACE;
#endif
qemu_loglevel = log_flags;
daemonized = is_daemonized();
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;
}
util/log: do not close and reopen log files when flags are turned off 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>
2022-11-08 17:00:31 +03:00
if (logfile) {
fflush(logfile);
if (changed_name && logfile != stderr) {
RCUCloseFILE *r = g_new0(RCUCloseFILE, 1);
r->fd = logfile;
util/log: do not close and reopen log files when flags are turned off 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>
2022-11-08 17:00:31 +03:00
qatomic_rcu_set(&global_file, NULL);
call_rcu(r, rcu_close_file, rcu);
util/log: do not close and reopen log files when flags are turned off 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>
2022-11-08 17:00:31 +03:00
logfile = NULL;
}
}
if (log_per_thread && daemonized) {
logfile = thread_file;
}
if (!logfile && need_to_open_file) {
if (filename) {
if (log_per_thread) {
logfile = qemu_log_trylock_with_err(errp);
if (!logfile) {
return false;
}
qemu_log_unlock(logfile);
} else {
logfile = fopen(filename, "w");
if (!logfile) {
error_setg_errno(errp, errno, "Error opening logfile %s",
filename);
return false;
}
}
/* In case we are a daemon redirect stderr to logfile */
if (daemonized) {
dup2(fileno(logfile), STDERR_FILENO);
fclose(logfile);
/*
* This will skip closing logfile in rcu_close_file()
* or qemu_log_thread_cleanup().
*/
logfile = stderr;
}
} else {
/* Default to stderr if no log file specified */
assert(!daemonized);
logfile = stderr;
}
if (log_per_thread && daemonized) {
thread_file = logfile;
} else {
qatomic_rcu_set(&global_file, logfile);
}
}
return true;
}
bool qemu_set_log(int log_flags, Error **errp)
{
return qemu_set_log_internal(NULL, false, log_flags, errp);
}
bool qemu_set_log_filename(const char *filename, Error **errp)
{
return qemu_set_log_internal(filename, true, qemu_loglevel, errp);
}
bool qemu_set_log_filename_flags(const char *name, int flags, Error **errp)
{
return qemu_set_log_internal(name, true, flags, errp);
}
/* Returns true if addr is in our debug filter or no filter defined
*/
bool qemu_log_in_addr_range(uint64_t addr)
{
if (debug_regions) {
int i = 0;
for (i = 0; i < debug_regions->len; i++) {
Range *range = &g_array_index(debug_regions, Range, i);
if (range_contains(range, addr)) {
return true;
}
}
return false;
} else {
return true;
}
}
void qemu_set_dfilter_ranges(const char *filter_spec, Error **errp)
{
gchar **ranges = g_strsplit(filter_spec, ",", 0);
int i;
if (debug_regions) {
g_array_unref(debug_regions);
debug_regions = NULL;
}
debug_regions = g_array_sized_new(FALSE, FALSE,
sizeof(Range), g_strv_length(ranges));
for (i = 0; ranges[i]; i++) {
const char *r = ranges[i];
const char *range_op, *r2, *e;
uint64_t r1val, r2val, lob, upb;
struct Range range;
range_op = strstr(r, "-");
r2 = range_op ? range_op + 1 : NULL;
if (!range_op) {
range_op = strstr(r, "+");
r2 = range_op ? range_op + 1 : NULL;
}
if (!range_op) {
range_op = strstr(r, "..");
r2 = range_op ? range_op + 2 : NULL;
}
if (!range_op) {
error_setg(errp, "Bad range specifier");
goto out;
}
if (qemu_strtou64(r, &e, 0, &r1val)
|| e != range_op) {
error_setg(errp, "Invalid number to the left of %.*s",
(int)(r2 - range_op), range_op);
goto out;
}
if (qemu_strtou64(r2, NULL, 0, &r2val)) {
error_setg(errp, "Invalid number to the right of %.*s",
(int)(r2 - range_op), range_op);
goto out;
}
switch (*range_op) {
case '+':
lob = r1val;
upb = r1val + r2val - 1;
break;
case '-':
upb = r1val;
lob = r1val - (r2val - 1);
break;
case '.':
lob = r1val;
upb = r2val;
break;
default:
g_assert_not_reached();
}
if (lob > upb) {
error_setg(errp, "Invalid range");
goto out;
}
range_set_bounds(&range, lob, upb);
g_array_append_val(debug_regions, range);
}
out:
g_strfreev(ranges);
}
const QEMULogItem qemu_log_items[] = {
{ CPU_LOG_TB_OUT_ASM, "out_asm",
"show generated host assembly code for each compiled TB" },
{ CPU_LOG_TB_IN_ASM, "in_asm",
"show target assembly code for each compiled TB" },
{ CPU_LOG_TB_OP, "op",
"show micro ops for each compiled TB" },
{ CPU_LOG_TB_OP_OPT, "op_opt",
"show micro ops after optimization" },
{ CPU_LOG_TB_OP_IND, "op_ind",
"show micro ops before indirect lowering" },
{ CPU_LOG_INT, "int",
"show interrupts/exceptions in short format" },
{ CPU_LOG_EXEC, "exec",
"show trace before each executed TB (lots of logs)" },
{ CPU_LOG_TB_CPU, "cpu",
"show CPU registers before entering a TB (lots of logs)" },
{ CPU_LOG_TB_FPU, "fpu",
"include FPU registers in the 'cpu' logging" },
{ CPU_LOG_MMU, "mmu",
"log MMU-related activities" },
{ CPU_LOG_PCALL, "pcall",
"x86 only: show protected mode far calls/returns/exceptions" },
{ CPU_LOG_RESET, "cpu_reset",
"show CPU state before CPU resets" },
{ LOG_UNIMP, "unimp",
"log unimplemented functionality" },
{ LOG_GUEST_ERROR, "guest_errors",
"log when the guest OS does something invalid (eg accessing a\n"
"non-existent register)" },
{ CPU_LOG_PAGE, "page",
"dump pages at beginning of user mode emulation" },
{ CPU_LOG_TB_NOCHAIN, "nochain",
"do not chain compiled TBs so that \"exec\" and \"cpu\" show\n"
"complete traces" },
#ifdef CONFIG_PLUGIN
{ CPU_LOG_PLUGIN, "plugin", "output from TCG plugins"},
#endif
{ LOG_STRACE, "strace",
"log every user-mode syscall, its input, and its result" },
{ LOG_PER_THREAD, "tid",
"open a separate log file per thread; filename must contain '%d'" },
{ CPU_LOG_TB_VPU, "vpu",
"include VPU registers in the 'cpu' logging" },
{ 0, NULL, NULL },
};
/* takes a comma separated list of log masks. Return 0 if error. */
int qemu_str_to_log_mask(const char *str)
{
const QEMULogItem *item;
int mask = 0;
char **parts = g_strsplit(str, ",", 0);
char **tmp;
for (tmp = parts; tmp && *tmp; tmp++) {
if (g_str_equal(*tmp, "all")) {
for (item = qemu_log_items; item->mask != 0; item++) {
mask |= item->mask;
}
#ifdef CONFIG_TRACE_LOG
} else if (g_str_has_prefix(*tmp, "trace:") && (*tmp)[6] != '\0') {
trace_enable_events((*tmp) + 6);
mask |= LOG_TRACE;
#endif
} else {
for (item = qemu_log_items; item->mask != 0; item++) {
if (g_str_equal(*tmp, item->name)) {
goto found;
}
}
goto error;
found:
mask |= item->mask;
}
}
g_strfreev(parts);
return mask;
error:
g_strfreev(parts);
return 0;
}
void qemu_print_log_usage(FILE *f)
{
const QEMULogItem *item;
fprintf(f, "Log items (comma separated):\n");
for (item = qemu_log_items; item->mask != 0; item++) {
fprintf(f, "%-15s %s\n", item->name, item->help);
}
#ifdef CONFIG_TRACE_LOG
fprintf(f, "trace:PATTERN enable trace events\n");
fprintf(f, "\nUse \"-d trace:help\" to get a list of trace events.\n\n");
#endif
}