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