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