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