qemu

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

35
typedef struct RCUCloseFILE {
36
    struct rcu_head rcu;
37
    FILE *fd;
38
} RCUCloseFILE;
39

40
/* Mutex covering the other global_* variables. */
41
static QemuMutex global_mutex;
42
static char *global_filename;
43
static FILE *global_file;
44
static __thread FILE *thread_file;
45
static __thread Notifier qemu_log_thread_cleanup_notifier;
46

47
int qemu_loglevel;
48
static bool log_per_thread;
49
static GArray *debug_regions;
50

51
/* Returns true if qemu_log() will really write somewhere. */
52
bool 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. */
58
bool 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

68
static 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
static 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

90
static 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

130
FILE *qemu_log_trylock(void)
131
{
132
    return qemu_log_trylock_with_err(NULL);
133
}
134

135
void 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

146
void 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

159
static void __attribute__((__constructor__)) startup(void)
160
{
161
    qemu_mutex_init(&global_mutex);
162
}
163

164
static 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

177
typedef enum {
178
    vft_error,
179
    vft_stderr,
180
    vft_strdup,
181
    vft_pid_printf,
182
} ValidFilenameTemplateResult;
183

184
static ValidFilenameTemplateResult
185
valid_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 */
207
static 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
        }
302
        if (changed_name) {
303
            logfile = NULL;
304
        }
305
    }
306

307
    if (log_per_thread && daemonized) {
308
        logfile = thread_file;
309
    }
310

311
    if (!logfile && need_to_open_file) {
312
        if (filename) {
313
            if (log_per_thread) {
314
                logfile = qemu_log_trylock_with_err(errp);
315
                if (!logfile) {
316
                    return false;
317
                }
318
                qemu_log_unlock(logfile);
319
            } else {
320
                logfile = fopen(filename, "w");
321
                if (!logfile) {
322
                    error_setg_errno(errp, errno, "Error opening logfile %s",
323
                                     filename);
324
                    return false;
325
                }
326
            }
327
            /* In case we are a daemon redirect stderr to logfile */
328
            if (daemonized) {
329
                dup2(fileno(logfile), STDERR_FILENO);
330
                fclose(logfile);
331
                /*
332
                 * This will skip closing logfile in rcu_close_file()
333
                 * or qemu_log_thread_cleanup().
334
                 */
335
                logfile = stderr;
336
            }
337
        } else {
338
            /* Default to stderr if no log file specified */
339
            assert(!daemonized);
340
            logfile = stderr;
341
        }
342

343
        if (log_per_thread && daemonized) {
344
            thread_file = logfile;
345
        } else {
346
            qatomic_rcu_set(&global_file, logfile);
347
        }
348
    }
349
    return true;
350
}
351

352
bool qemu_set_log(int log_flags, Error **errp)
353
{
354
    return qemu_set_log_internal(NULL, false, log_flags, errp);
355
}
356

357
bool qemu_set_log_filename(const char *filename, Error **errp)
358
{
359
    return qemu_set_log_internal(filename, true, qemu_loglevel, errp);
360
}
361

362
bool qemu_set_log_filename_flags(const char *name, int flags, Error **errp)
363
{
364
    return qemu_set_log_internal(name, true, flags, errp);
365
}
366

367
/* Returns true if addr is in our debug filter or no filter defined
368
 */
369
bool qemu_log_in_addr_range(uint64_t addr)
370
{
371
    if (debug_regions) {
372
        int i = 0;
373
        for (i = 0; i < debug_regions->len; i++) {
374
            Range *range = &g_array_index(debug_regions, Range, i);
375
            if (range_contains(range, addr)) {
376
                return true;
377
            }
378
        }
379
        return false;
380
    } else {
381
        return true;
382
    }
383
}
384

385

386
void qemu_set_dfilter_ranges(const char *filter_spec, Error **errp)
387
{
388
    gchar **ranges = g_strsplit(filter_spec, ",", 0);
389
    int i;
390

391
    if (debug_regions) {
392
        g_array_unref(debug_regions);
393
        debug_regions = NULL;
394
    }
395

396
    debug_regions = g_array_sized_new(FALSE, FALSE,
397
                                      sizeof(Range), g_strv_length(ranges));
398
    for (i = 0; ranges[i]; i++) {
399
        const char *r = ranges[i];
400
        const char *range_op, *r2, *e;
401
        uint64_t r1val, r2val, lob, upb;
402
        struct Range range;
403

404
        range_op = strstr(r, "-");
405
        r2 = range_op ? range_op + 1 : NULL;
406
        if (!range_op) {
407
            range_op = strstr(r, "+");
408
            r2 = range_op ? range_op + 1 : NULL;
409
        }
410
        if (!range_op) {
411
            range_op = strstr(r, "..");
412
            r2 = range_op ? range_op + 2 : NULL;
413
        }
414
        if (!range_op) {
415
            error_setg(errp, "Bad range specifier");
416
            goto out;
417
        }
418

419
        if (qemu_strtou64(r, &e, 0, &r1val)
420
            || e != range_op) {
421
            error_setg(errp, "Invalid number to the left of %.*s",
422
                       (int)(r2 - range_op), range_op);
423
            goto out;
424
        }
425
        if (qemu_strtou64(r2, NULL, 0, &r2val)) {
426
            error_setg(errp, "Invalid number to the right of %.*s",
427
                       (int)(r2 - range_op), range_op);
428
            goto out;
429
        }
430

431
        switch (*range_op) {
432
        case '+':
433
            lob = r1val;
434
            upb = r1val + r2val - 1;
435
            break;
436
        case '-':
437
            upb = r1val;
438
            lob = r1val - (r2val - 1);
439
            break;
440
        case '.':
441
            lob = r1val;
442
            upb = r2val;
443
            break;
444
        default:
445
            g_assert_not_reached();
446
        }
447
        if (lob > upb) {
448
            error_setg(errp, "Invalid range");
449
            goto out;
450
        }
451
        range_set_bounds(&range, lob, upb);
452
        g_array_append_val(debug_regions, range);
453
    }
454
out:
455
    g_strfreev(ranges);
456
}
457

458
const QEMULogItem qemu_log_items[] = {
459
    { CPU_LOG_TB_OUT_ASM, "out_asm",
460
      "show generated host assembly code for each compiled TB" },
461
    { CPU_LOG_TB_IN_ASM, "in_asm",
462
      "show target assembly code for each compiled TB" },
463
    { CPU_LOG_TB_OP, "op",
464
      "show micro ops for each compiled TB" },
465
    { CPU_LOG_TB_OP_OPT, "op_opt",
466
      "show micro ops after optimization" },
467
    { CPU_LOG_TB_OP_IND, "op_ind",
468
      "show micro ops before indirect lowering" },
469
#ifdef CONFIG_PLUGIN
470
    { LOG_TB_OP_PLUGIN, "op_plugin",
471
      "show micro ops before plugin injection" },
472
#endif
473
    { CPU_LOG_INT, "int",
474
      "show interrupts/exceptions in short format" },
475
    { CPU_LOG_EXEC, "exec",
476
      "show trace before each executed TB (lots of logs)" },
477
    { CPU_LOG_TB_CPU, "cpu",
478
      "show CPU registers before entering a TB (lots of logs)" },
479
    { CPU_LOG_TB_FPU, "fpu",
480
      "include FPU registers in the 'cpu' logging" },
481
    { CPU_LOG_MMU, "mmu",
482
      "log MMU-related activities" },
483
    { CPU_LOG_PCALL, "pcall",
484
      "x86 only: show protected mode far calls/returns/exceptions" },
485
    { CPU_LOG_RESET, "cpu_reset",
486
      "show CPU state before CPU resets" },
487
    { LOG_UNIMP, "unimp",
488
      "log unimplemented functionality" },
489
    { LOG_GUEST_ERROR, "guest_errors",
490
      "log when the guest OS does something invalid (eg accessing a\n"
491
      "non-existent register)" },
492
    { CPU_LOG_PAGE, "page",
493
      "dump pages at beginning of user mode emulation" },
494
    { CPU_LOG_TB_NOCHAIN, "nochain",
495
      "do not chain compiled TBs so that \"exec\" and \"cpu\" show\n"
496
      "complete traces" },
497
#ifdef CONFIG_PLUGIN
498
    { CPU_LOG_PLUGIN, "plugin", "output from TCG plugins"},
499
#endif
500
    { LOG_STRACE, "strace",
501
      "log every user-mode syscall, its input, and its result" },
502
    { LOG_PER_THREAD, "tid",
503
      "open a separate log file per thread; filename must contain '%d'" },
504
    { CPU_LOG_TB_VPU, "vpu",
505
      "include VPU registers in the 'cpu' logging" },
506
    { 0, NULL, NULL },
507
};
508

509
/* takes a comma separated list of log masks. Return 0 if error. */
510
int qemu_str_to_log_mask(const char *str)
511
{
512
    const QEMULogItem *item;
513
    int mask = 0;
514
    char **parts = g_strsplit(str, ",", 0);
515
    char **tmp;
516

517
    for (tmp = parts; tmp && *tmp; tmp++) {
518
        if (g_str_equal(*tmp, "all")) {
519
            for (item = qemu_log_items; item->mask != 0; item++) {
520
                mask |= item->mask;
521
            }
522
#ifdef CONFIG_TRACE_LOG
523
        } else if (g_str_has_prefix(*tmp, "trace:") && (*tmp)[6] != '\0') {
524
            trace_enable_events((*tmp) + 6);
525
            mask |= LOG_TRACE;
526
#endif
527
        } else {
528
            for (item = qemu_log_items; item->mask != 0; item++) {
529
                if (g_str_equal(*tmp, item->name)) {
530
                    goto found;
531
                }
532
            }
533
            goto error;
534
        found:
535
            mask |= item->mask;
536
        }
537
    }
538

539
    g_strfreev(parts);
540
    return mask;
541

542
 error:
543
    g_strfreev(parts);
544
    return 0;
545
}
546

547
void qemu_print_log_usage(FILE *f)
548
{
549
    const QEMULogItem *item;
550
    fprintf(f, "Log items (comma separated):\n");
551
    for (item = qemu_log_items; item->mask != 0; item++) {
552
        fprintf(f, "%-15s %s\n", item->name, item->help);
553
    }
554
#ifdef CONFIG_TRACE_LOG
555
    fprintf(f, "trace:PATTERN   enable trace events\n");
556
    fprintf(f, "\nUse \"-d trace:help\" to get a list of trace events.\n\n");
557
#endif
558
}
559