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