xref: /openbmc/qemu/util/log.c (revision 9d49b1c9edf829e571093088ddff0b73db3110c6)
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