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_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     { CPU_LOG_INT, "int",
 470       "show interrupts/exceptions in short format" },
 471     { CPU_LOG_EXEC, "exec",
 472       "show trace before each executed TB (lots of logs)" },
 473     { CPU_LOG_TB_CPU, "cpu",
 474       "show CPU registers before entering a TB (lots of logs)" },
 475     { CPU_LOG_TB_FPU, "fpu",
 476       "include FPU registers in the 'cpu' logging" },
 477     { CPU_LOG_MMU, "mmu",
 478       "log MMU-related activities" },
 479     { CPU_LOG_PCALL, "pcall",
 480       "x86 only: show protected mode far calls/returns/exceptions" },
 481     { CPU_LOG_RESET, "cpu_reset",
 482       "show CPU state before CPU resets" },
 483     { LOG_UNIMP, "unimp",
 484       "log unimplemented functionality" },
 485     { LOG_GUEST_ERROR, "guest_errors",
 486       "log when the guest OS does something invalid (eg accessing a\n"
 487       "non-existent register)" },
 488     { CPU_LOG_PAGE, "page",
 489       "dump pages at beginning of user mode emulation" },
 490     { CPU_LOG_TB_NOCHAIN, "nochain",
 491       "do not chain compiled TBs so that \"exec\" and \"cpu\" show\n"
 492       "complete traces" },
 493 #ifdef CONFIG_PLUGIN
 494     { CPU_LOG_PLUGIN, "plugin", "output from TCG plugins"},
 495 #endif
 496     { LOG_STRACE, "strace",
 497       "log every user-mode syscall, its input, and its result" },
 498     { LOG_PER_THREAD, "tid",
 499       "open a separate log file per thread; filename must contain '%d'" },
 500     { CPU_LOG_TB_VPU, "vpu",
 501       "include VPU registers in the 'cpu' logging" },
 502     { 0, NULL, NULL },
 503 };
 504
 505 /* takes a comma separated list of log masks. Return 0 if error. */
 506 int qemu_str_to_log_mask(const char *str)
 507 {
 508     const QEMULogItem *item;
 509     int mask = 0;
 510     char **parts = g_strsplit(str, ",", 0);
 511     char **tmp;
 512
 513     for (tmp = parts; tmp && *tmp; tmp++) {
 514         if (g_str_equal(*tmp, "all")) {
 515             for (item = qemu_log_items; item->mask != 0; item++) {
 516                 mask |= item->mask;
 517             }
 518 #ifdef CONFIG_TRACE_LOG
 519         } else if (g_str_has_prefix(*tmp, "trace:") && (*tmp)[6] != '\0') {
 520             trace_enable_events((*tmp) + 6);
 521             mask |= LOG_TRACE;
 522 #endif
 523         } else {
 524             for (item = qemu_log_items; item->mask != 0; item++) {
 525                 if (g_str_equal(*tmp, item->name)) {
 526                     goto found;
 527                 }
 528             }
 529             goto error;
 530         found:
 531             mask |= item->mask;
 532         }
 533     }
 534
 535     g_strfreev(parts);
 536     return mask;
 537
 538  error:
 539     g_strfreev(parts);
 540     return 0;
 541 }
 542
 543 void qemu_print_log_usage(FILE *f)
 544 {
 545     const QEMULogItem *item;
 546     fprintf(f, "Log items (comma separated):\n");
 547     for (item = qemu_log_items; item->mask != 0; item++) {
 548         fprintf(f, "%-15s %s\n", item->name, item->help);
 549     }
 550 #ifdef CONFIG_TRACE_LOG
 551     fprintf(f, "trace:PATTERN   enable trace events\n");
 552     fprintf(f, "\nUse \"-d trace:help\" to get a list of trace events.\n\n");
 553 #endif
 554 }