qemu/util/log.c
<<
>>
Prefs
   1/*
   2 * Logging support
   3 *
   4 *  Copyright (c) 2003 Fabrice Bellard
   5 *
   6 * This library is free software; you can redistribute it and/or
   7 * modify it under the terms of the GNU Lesser General Public
   8 * License as published by the Free Software Foundation; either
   9 * version 2.1 of the License, or (at your option) any later version.
  10 *
  11 * This library is distributed in the hope that it will be useful,
  12 * but WITHOUT ANY WARRANTY; without even the implied warranty of
  13 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  14 * Lesser General Public License for more details.
  15 *
  16 * You should have received a copy of the GNU Lesser General Public
  17 * License along with this library; if not, see <http://www.gnu.org/licenses/>.
  18 */
  19
  20#include "qemu/osdep.h"
  21#include "qemu/log.h"
  22#include "qemu/range.h"
  23#include "qemu/error-report.h"
  24#include "qapi/error.h"
  25#include "qemu/cutils.h"
  26#include "trace/control.h"
  27#include "qemu/thread.h"
  28#include "qemu/lockable.h"
  29#include "qemu/rcu.h"
  30#ifdef CONFIG_LINUX
  31#include <sys/syscall.h>
  32#endif
  33
  34
  35typedef struct RCUCloseFILE {
  36    struct rcu_head rcu;
  37    FILE *fd;
  38} RCUCloseFILE;
  39
  40/* Mutex covering the other global_* variables. */
  41static QemuMutex global_mutex;
  42static char *global_filename;
  43static FILE *global_file;
  44static __thread FILE *thread_file;
  45static __thread Notifier qemu_log_thread_cleanup_notifier;
  46
  47int qemu_loglevel;
  48static bool log_append;
  49static bool log_per_thread;
  50static GArray *debug_regions;
  51
  52/* Returns true if qemu_log() will really write somewhere. */
  53bool qemu_log_enabled(void)
  54{
  55    return log_per_thread || qatomic_read(&global_file) != NULL;
  56}
  57
  58/* Returns true if qemu_log() will write somewhere other than stderr. */
  59bool qemu_log_separate(void)
  60{
  61    if (log_per_thread) {
  62        return true;
  63    } else {
  64        FILE *logfile = qatomic_read(&global_file);
  65        return logfile && logfile != stderr;
  66    }
  67}
  68
  69static int log_thread_id(void)
  70{
  71#ifdef CONFIG_GETTID
  72    return gettid();
  73#elif defined(SYS_gettid)
  74    return syscall(SYS_gettid);
  75#else
  76    static int counter;
  77    return qatomic_fetch_inc(&counter);
  78#endif
  79}
  80
  81static void qemu_log_thread_cleanup(Notifier *n, void *unused)
  82{
  83    fclose(thread_file);
  84    thread_file = NULL;
  85}
  86
  87/* Lock/unlock output. */
  88
  89FILE *qemu_log_trylock(void)
  90{
  91    FILE *logfile;
  92
  93    logfile = thread_file;
  94    if (!logfile) {
  95        if (log_per_thread) {
  96            g_autofree char *filename
  97                = g_strdup_printf(global_filename, log_thread_id());
  98            logfile = fopen(filename, "w");
  99            if (!logfile) {
 100                return NULL;
 101            }
 102            thread_file = logfile;
 103            qemu_log_thread_cleanup_notifier.notify = qemu_log_thread_cleanup;
 104            qemu_thread_atexit_add(&qemu_log_thread_cleanup_notifier);
 105        } else {
 106            rcu_read_lock();
 107            /*
 108             * FIXME: typeof_strip_qual, as used by qatomic_rcu_read,
 109             * does not work with pointers to undefined structures,
 110             * such as we have with struct _IO_FILE and musl libc.
 111             * Since all we want is a read of a pointer, cast to void**,
 112             * which does work with typeof_strip_qual.
 113             */
 114            logfile = qatomic_rcu_read((void **)&global_file);
 115            if (!logfile) {
 116                rcu_read_unlock();
 117                return NULL;
 118            }
 119        }
 120    }
 121
 122    qemu_flockfile(logfile);
 123    return logfile;
 124}
 125
 126void qemu_log_unlock(FILE *logfile)
 127{
 128    if (logfile) {
 129        fflush(logfile);
 130        qemu_funlockfile(logfile);
 131        if (!log_per_thread) {
 132            rcu_read_unlock();
 133        }
 134    }
 135}
 136
 137void qemu_log(const char *fmt, ...)
 138{
 139    FILE *f = qemu_log_trylock();
 140    if (f) {
 141        va_list ap;
 142
 143        va_start(ap, fmt);
 144        vfprintf(f, fmt, ap);
 145        va_end(ap);
 146        qemu_log_unlock(f);
 147    }
 148}
 149
 150static void __attribute__((__constructor__)) startup(void)
 151{
 152    qemu_mutex_init(&global_mutex);
 153}
 154
 155static void rcu_close_file(RCUCloseFILE *r)
 156{
 157    fclose(r->fd);
 158    g_free(r);
 159}
 160
 161/**
 162 * valid_filename_template:
 163 *
 164 * Validate the filename template.  Require %d if per_thread, allow it
 165 * otherwise; require no other % within the template.
 166 */
 167
 168typedef enum {
 169    vft_error,
 170    vft_stderr,
 171    vft_strdup,
 172    vft_pid_printf,
 173} ValidFilenameTemplateResult;
 174
 175static ValidFilenameTemplateResult
 176valid_filename_template(const char *filename, bool per_thread, Error **errp)
 177{
 178    if (filename) {
 179        char *pidstr = strstr(filename, "%");
 180
 181        if (pidstr) {
 182            /* We only accept one %d, no other format strings */
 183            if (pidstr[1] != 'd' || strchr(pidstr + 2, '%')) {
 184                error_setg(errp, "Bad logfile template: %s", filename);
 185                return 0;
 186            }
 187            return per_thread ? vft_strdup : vft_pid_printf;
 188        }
 189    }
 190    if (per_thread) {
 191        error_setg(errp, "Filename template with '%%d' required for 'tid'");
 192        return vft_error;
 193    }
 194    return filename ? vft_strdup : vft_stderr;
 195}
 196
 197/* enable or disable low levels log */
 198static bool qemu_set_log_internal(const char *filename, bool changed_name,
 199                                  int log_flags, Error **errp)
 200{
 201    bool need_to_open_file;
 202    bool daemonized;
 203    bool per_thread;
 204    FILE *logfile;
 205
 206    QEMU_LOCK_GUARD(&global_mutex);
 207    logfile = global_file;
 208
 209    /* The per-thread flag is immutable. */
 210    if (log_per_thread) {
 211        log_flags |= LOG_PER_THREAD;
 212    } else {
 213        if (global_filename) {
 214            log_flags &= ~LOG_PER_THREAD;
 215        }
 216    }
 217
 218    per_thread = log_flags & LOG_PER_THREAD;
 219
 220    if (changed_name) {
 221        char *newname = NULL;
 222
 223        /*
 224         * Once threads start opening their own log files, we have no
 225         * easy mechanism to tell them all to close and re-open.
 226         * There seems little cause to do so either -- this option
 227         * will most often be used at user-only startup.
 228         */
 229        if (log_per_thread) {
 230            error_setg(errp, "Cannot change log filename after setting 'tid'");
 231            return false;
 232        }
 233
 234        switch (valid_filename_template(filename, per_thread, errp)) {
 235        case vft_error:
 236            return false;
 237        case vft_stderr:
 238            break;
 239        case vft_strdup:
 240            newname = g_strdup(filename);
 241            break;
 242        case vft_pid_printf:
 243            newname = g_strdup_printf(filename, getpid());
 244            break;
 245        }
 246
 247        g_free(global_filename);
 248        global_filename = newname;
 249        filename = newname;
 250    } else {
 251        filename = global_filename;
 252        if (per_thread &&
 253            valid_filename_template(filename, true, errp) == vft_error) {
 254            return false;
 255        }
 256    }
 257
 258    /* Once the per-thread flag is set, it cannot be unset. */
 259    if (per_thread) {
 260        log_per_thread = true;
 261    }
 262    /* The flag itself is not relevant for need_to_open_file. */
 263    log_flags &= ~LOG_PER_THREAD;
 264#ifdef CONFIG_TRACE_LOG
 265    log_flags |= LOG_TRACE;
 266#endif
 267    qemu_loglevel = log_flags;
 268
 269    /*
 270     * In all cases we only log if qemu_loglevel is set.
 271     * Also:
 272     *   If per-thread, open the file for each thread in qemu_log_lock.
 273     *   If not daemonized we will always log either to stderr
 274     *     or to a file (if there is a filename).
 275     *   If we are daemonized, we will only log if there is a filename.
 276     */
 277    daemonized = is_daemonized();
 278    need_to_open_file = log_flags && !per_thread && (!daemonized || filename);
 279
 280    if (logfile && (!need_to_open_file || changed_name)) {
 281        qatomic_rcu_set(&global_file, NULL);
 282        if (logfile != stderr) {
 283            RCUCloseFILE *r = g_new0(RCUCloseFILE, 1);
 284            r->fd = logfile;
 285            call_rcu(r, rcu_close_file, rcu);
 286        }
 287        logfile = NULL;
 288    }
 289
 290    if (!logfile && need_to_open_file) {
 291        if (filename) {
 292            logfile = fopen(filename, log_append ? "a" : "w");
 293            if (!logfile) {
 294                error_setg_errno(errp, errno, "Error opening logfile %s",
 295                                 filename);
 296                return false;
 297            }
 298            /* In case we are a daemon redirect stderr to logfile */
 299            if (daemonized) {
 300                dup2(fileno(logfile), STDERR_FILENO);
 301                fclose(logfile);
 302                /* This will skip closing logfile in rcu_close_file. */
 303                logfile = stderr;
 304            }
 305        } else {
 306            /* Default to stderr if no log file specified */
 307            assert(!daemonized);
 308            logfile = stderr;
 309        }
 310
 311        log_append = 1;
 312
 313        qatomic_rcu_set(&global_file, logfile);
 314    }
 315    return true;
 316}
 317
 318bool qemu_set_log(int log_flags, Error **errp)
 319{
 320    return qemu_set_log_internal(NULL, false, log_flags, errp);
 321}
 322
 323bool qemu_set_log_filename(const char *filename, Error **errp)
 324{
 325    return qemu_set_log_internal(filename, true, qemu_loglevel, errp);
 326}
 327
 328bool qemu_set_log_filename_flags(const char *name, int flags, Error **errp)
 329{
 330    return qemu_set_log_internal(name, true, flags, errp);
 331}
 332
 333/* Returns true if addr is in our debug filter or no filter defined
 334 */
 335bool qemu_log_in_addr_range(uint64_t addr)
 336{
 337    if (debug_regions) {
 338        int i = 0;
 339        for (i = 0; i < debug_regions->len; i++) {
 340            Range *range = &g_array_index(debug_regions, Range, i);
 341            if (range_contains(range, addr)) {
 342                return true;
 343            }
 344        }
 345        return false;
 346    } else {
 347        return true;
 348    }
 349}
 350
 351
 352void qemu_set_dfilter_ranges(const char *filter_spec, Error **errp)
 353{
 354    gchar **ranges = g_strsplit(filter_spec, ",", 0);
 355    int i;
 356
 357    if (debug_regions) {
 358        g_array_unref(debug_regions);
 359        debug_regions = NULL;
 360    }
 361
 362    debug_regions = g_array_sized_new(FALSE, FALSE,
 363                                      sizeof(Range), g_strv_length(ranges));
 364    for (i = 0; ranges[i]; i++) {
 365        const char *r = ranges[i];
 366        const char *range_op, *r2, *e;
 367        uint64_t r1val, r2val, lob, upb;
 368        struct Range range;
 369
 370        range_op = strstr(r, "-");
 371        r2 = range_op ? range_op + 1 : NULL;
 372        if (!range_op) {
 373            range_op = strstr(r, "+");
 374            r2 = range_op ? range_op + 1 : NULL;
 375        }
 376        if (!range_op) {
 377            range_op = strstr(r, "..");
 378            r2 = range_op ? range_op + 2 : NULL;
 379        }
 380        if (!range_op) {
 381            error_setg(errp, "Bad range specifier");
 382            goto out;
 383        }
 384
 385        if (qemu_strtou64(r, &e, 0, &r1val)
 386            || e != range_op) {
 387            error_setg(errp, "Invalid number to the left of %.*s",
 388                       (int)(r2 - range_op), range_op);
 389            goto out;
 390        }
 391        if (qemu_strtou64(r2, NULL, 0, &r2val)) {
 392            error_setg(errp, "Invalid number to the right of %.*s",
 393                       (int)(r2 - range_op), range_op);
 394            goto out;
 395        }
 396
 397        switch (*range_op) {
 398        case '+':
 399            lob = r1val;
 400            upb = r1val + r2val - 1;
 401            break;
 402        case '-':
 403            upb = r1val;
 404            lob = r1val - (r2val - 1);
 405            break;
 406        case '.':
 407            lob = r1val;
 408            upb = r2val;
 409            break;
 410        default:
 411            g_assert_not_reached();
 412        }
 413        if (lob > upb) {
 414            error_setg(errp, "Invalid range");
 415            goto out;
 416        }
 417        range_set_bounds(&range, lob, upb);
 418        g_array_append_val(debug_regions, range);
 419    }
 420out:
 421    g_strfreev(ranges);
 422}
 423
 424const QEMULogItem qemu_log_items[] = {
 425    { CPU_LOG_TB_OUT_ASM, "out_asm",
 426      "show generated host assembly code for each compiled TB" },
 427    { CPU_LOG_TB_IN_ASM, "in_asm",
 428      "show target assembly code for each compiled TB" },
 429    { CPU_LOG_TB_OP, "op",
 430      "show micro ops for each compiled TB" },
 431    { CPU_LOG_TB_OP_OPT, "op_opt",
 432      "show micro ops after optimization" },
 433    { CPU_LOG_TB_OP_IND, "op_ind",
 434      "show micro ops before indirect lowering" },
 435    { CPU_LOG_INT, "int",
 436      "show interrupts/exceptions in short format" },
 437    { CPU_LOG_EXEC, "exec",
 438      "show trace before each executed TB (lots of logs)" },
 439    { CPU_LOG_TB_CPU, "cpu",
 440      "show CPU registers before entering a TB (lots of logs)" },
 441    { CPU_LOG_TB_FPU, "fpu",
 442      "include FPU registers in the 'cpu' logging" },
 443    { CPU_LOG_MMU, "mmu",
 444      "log MMU-related activities" },
 445    { CPU_LOG_PCALL, "pcall",
 446      "x86 only: show protected mode far calls/returns/exceptions" },
 447    { CPU_LOG_RESET, "cpu_reset",
 448      "show CPU state before CPU resets" },
 449    { LOG_UNIMP, "unimp",
 450      "log unimplemented functionality" },
 451    { LOG_GUEST_ERROR, "guest_errors",
 452      "log when the guest OS does something invalid (eg accessing a\n"
 453      "non-existent register)" },
 454    { CPU_LOG_PAGE, "page",
 455      "dump pages at beginning of user mode emulation" },
 456    { CPU_LOG_TB_NOCHAIN, "nochain",
 457      "do not chain compiled TBs so that \"exec\" and \"cpu\" show\n"
 458      "complete traces" },
 459#ifdef CONFIG_PLUGIN
 460    { CPU_LOG_PLUGIN, "plugin", "output from TCG plugins\n"},
 461#endif
 462    { LOG_STRACE, "strace",
 463      "log every user-mode syscall, its input, and its result" },
 464    { LOG_PER_THREAD, "tid",
 465      "open a separate log file per thread; filename must contain '%d'" },
 466    { 0, NULL, NULL },
 467};
 468
 469/* takes a comma separated list of log masks. Return 0 if error. */
 470int qemu_str_to_log_mask(const char *str)
 471{
 472    const QEMULogItem *item;
 473    int mask = 0;
 474    char **parts = g_strsplit(str, ",", 0);
 475    char **tmp;
 476
 477    for (tmp = parts; tmp && *tmp; tmp++) {
 478        if (g_str_equal(*tmp, "all")) {
 479            for (item = qemu_log_items; item->mask != 0; item++) {
 480                mask |= item->mask;
 481            }
 482#ifdef CONFIG_TRACE_LOG
 483        } else if (g_str_has_prefix(*tmp, "trace:") && (*tmp)[6] != '\0') {
 484            trace_enable_events((*tmp) + 6);
 485            mask |= LOG_TRACE;
 486#endif
 487        } else {
 488            for (item = qemu_log_items; item->mask != 0; item++) {
 489                if (g_str_equal(*tmp, item->name)) {
 490                    goto found;
 491                }
 492            }
 493            goto error;
 494        found:
 495            mask |= item->mask;
 496        }
 497    }
 498
 499    g_strfreev(parts);
 500    return mask;
 501
 502 error:
 503    g_strfreev(parts);
 504    return 0;
 505}
 506
 507void qemu_print_log_usage(FILE *f)
 508{
 509    const QEMULogItem *item;
 510    fprintf(f, "Log items (comma separated):\n");
 511    for (item = qemu_log_items; item->mask != 0; item++) {
 512        fprintf(f, "%-15s %s\n", item->name, item->help);
 513    }
 514#ifdef CONFIG_TRACE_LOG
 515    fprintf(f, "trace:PATTERN   enable trace events\n");
 516    fprintf(f, "\nUse \"-d trace:help\" to get a list of trace events.\n\n");
 517#endif
 518}
 519