util/log.c

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