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