util/log.c

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

unsigned 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();
                error_setg(errp, "Global log file output is not open");
                return NULL;
            }
        }
    }

    qemu_flockfile(logfile);
    return logfile;
}

/*
 * Zero if there's been no opening qemu_log_trylock call,
 * indicating the need for message context to be emitted
 *
 * Non-zero if we're in the middle of printing a message,
 * possibly over multiple lines and must skip further
 * message context
 */
static __thread unsigned int log_depth;

FILE *qemu_log_trylock(void)
{
    FILE *f = qemu_log_trylock_with_err(NULL);
    log_depth++;
    return f;
}

FILE *qemu_log_trylock_with_context(void)
{
    FILE *f = qemu_log_trylock();
    if (f && log_depth == 1 && message_with_timestamp) {
        g_autofree const char *timestr = NULL;
        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
        timestr = g_date_time_format_iso8601(dt);
        fprintf(f, "%s ", timestr);
    }
    return f;
}

void qemu_log_unlock(FILE *logfile)
{
    assert(log_depth);
    log_depth--;
    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_with_context();
    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) {
        const 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;
    }

    if (logfile) {
        fflush(logfile);
        if (changed_name && logfile != stderr) {
            RCUCloseFILE *r = g_new0(RCUCloseFILE, 1);
            r->fd = logfile;
            qatomic_rcu_set(&global_file, NULL);
            call_rcu(r, rcu_close_file, rcu);
        }
        if (changed_name) {
            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" },
#ifdef CONFIG_PLUGIN
    { LOG_TB_OP_PLUGIN, "op_plugin",
      "show micro ops before plugin injection" },
#endif
    { 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" },
    { LOG_INVALID_MEM, "invalid_mem",
      "log invalid memory accesses" },
    { 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
}

#ifdef CONFIG_HAVE_RUST
ssize_t rust_fwrite(const void *ptr, size_t size, size_t nmemb, FILE *stream)
{
    /*
     * Same as fwrite, but return -errno because Rust libc does not provide
     * portable access to errno. :(
     */
    int ret = fwrite(ptr, size, nmemb, stream);
    return ret < 0 ? -errno : 0;
}
#endif