| 1 | #include <bootstage_condition.h> |
| 2 | #include <console/printf.h> |
| 3 | #include <dbg.h> |
| 4 | #include <linker/symbol_table.h> |
| 5 | #include <linker/symbols.h> |
| 6 | #include <log.h> |
| 7 | #include <mem/alloc.h> |
| 8 | #include <mem/alloc_or_die.h> |
| 9 | #include <mem/vmm.h> |
| 10 | #include <ndjson.h> |
| 11 | #include <sch/sched.h> |
| 12 | #include <smp/core.h> |
| 13 | #include <stdarg.h> |
| 14 | #include <stddef.h> |
| 15 | #include <stdint.h> |
| 16 | #include <string.h> |
| 17 | #include <structures/locked_list.h> |
| 18 | #include <thread/thread.h> |
| 19 | #include <time/time.h> |
| 20 | |
| 21 | NDJSON_DECLARE(log_message, NDJSON_SECTION_LOG, NDJSON_KIND_MESSAGE, 1, |
| 22 | NDJSON_STR(site), NDJSON_STR(level), NDJSON_STR(msg), |
| 23 | NDJSON_STR(file), NDJSON_U64(line), NDJSON_STR(func)); |
| 24 | |
| 25 | #define LOG_IMPORTANT_RETRY 32 |
| 26 | LOG_SITE_DECLARE(global, .flags = LOG_SITE_DEFAULT, |
| 27 | .capacity = LOG_SITE_CAPACITY_DEFAULT, |
| 28 | .dump_opts = LOG_DUMP_CONSOLE, .enabled_mask = LOG_SITE_ALL); |
| 29 | |
| 30 | LOG_HANDLE_DECLARE(global, .flags = LOG_HANDLE_PRINT); |
| 31 | |
| 32 | struct log_globals { |
| 33 | bool initialized; |
| 34 | struct locked_list list; |
| 35 | }; |
| 36 | |
| 37 | struct log_globals log_global = {0}; |
| 38 | |
| 39 | /* NULL until the blob has been stamped, which only an unpatched image should |
| 40 | * ever hit. The table cannot go stale any more: it is written into the linked |
| 41 | * kernel after the fact, so it always describes this exact image */ |
| 42 | static const struct kernel_syms_hdr *(void) { |
| 43 | const struct kernel_syms_hdr *hdr = (const void *) kernel_syms_blob; |
| 44 | |
| 45 | if (hdr->magic != KERNEL_SYMS_MAGIC || !hdr->count) |
| 46 | return NULL; |
| 47 | |
| 48 | return hdr; |
| 49 | } |
| 50 | |
| 51 | static void syms_warn_if_missing(void) { |
| 52 | if (syms_header()) |
| 53 | return; |
| 54 | |
| 55 | printf(format: " <no symbol table: .kernel_syms was never stamped, " |
| 56 | "rebuild to symbolize>\n" ); |
| 57 | } |
| 58 | |
| 59 | static const char *find_symbol(uint64_t addr, uint64_t *out_sym_addr) { |
| 60 | const struct kernel_syms_hdr *hdr = syms_header(); |
| 61 | |
| 62 | if (out_sym_addr) |
| 63 | *out_sym_addr = 0; |
| 64 | |
| 65 | if (!hdr) |
| 66 | return NULL; |
| 67 | |
| 68 | const struct kernel_sym *tab = (const void *) (hdr + 1); |
| 69 | const char *strtab = kernel_syms_blob + hdr->strtab_off; |
| 70 | |
| 71 | /* Sorted by address, so bisect for the last entry at or below addr. Worth |
| 72 | * it here: this runs from panic paths where a scan of every symbol is the |
| 73 | * last thing we want */ |
| 74 | uint32_t lo = 0, hi = hdr->count; |
| 75 | while (lo < hi) { |
| 76 | uint32_t mid = lo + (hi - lo) / 2; |
| 77 | if (tab[mid].addr <= addr) |
| 78 | lo = mid + 1; |
| 79 | else |
| 80 | hi = mid; |
| 81 | } |
| 82 | |
| 83 | if (!lo) |
| 84 | return NULL; |
| 85 | |
| 86 | const struct kernel_sym *best = &tab[lo - 1]; |
| 87 | |
| 88 | if (out_sym_addr) |
| 89 | *out_sym_addr = best->addr; |
| 90 | |
| 91 | return strtab + best->name_off; |
| 92 | } |
| 93 | |
| 94 | static const struct kernel_lines_hdr *(void) { |
| 95 | const struct kernel_syms_hdr *hdr = syms_header(); |
| 96 | |
| 97 | if (!hdr || !hdr->lines_off) |
| 98 | return NULL; |
| 99 | |
| 100 | const struct kernel_lines_hdr *lines = |
| 101 | (const void *) (kernel_syms_blob + hdr->lines_off); |
| 102 | |
| 103 | if (lines->magic != KERNEL_LINES_MAGIC || !lines->count) |
| 104 | return NULL; |
| 105 | |
| 106 | return lines; |
| 107 | } |
| 108 | |
| 109 | static uint64_t uleb_next(const uint8_t **p, const uint8_t *end) { |
| 110 | uint64_t v = 0; |
| 111 | unsigned shift = 0; |
| 112 | |
| 113 | while (*p < end) { |
| 114 | uint8_t byte = *(*p)++; |
| 115 | |
| 116 | v |= (uint64_t) (byte & 0x7f) << shift; |
| 117 | if (!(byte & 0x80)) |
| 118 | break; |
| 119 | |
| 120 | shift += 7; |
| 121 | if (shift >= 64) |
| 122 | break; |
| 123 | } |
| 124 | |
| 125 | return v; |
| 126 | } |
| 127 | |
| 128 | static int64_t unzigzag(uint64_t v) { |
| 129 | return (v & 1) ? -(int64_t) (v >> 1) - 1 : (int64_t) (v >> 1); |
| 130 | } |
| 131 | |
| 132 | /* Name of the file'th entry in the table, or NULL if it runs off the end */ |
| 133 | static const char *lines_file_name(const struct kernel_lines_hdr *lines, |
| 134 | int64_t want) { |
| 135 | if (want < 0) |
| 136 | return NULL; |
| 137 | |
| 138 | const char *base = (const char *) lines + lines->files_off; |
| 139 | const char *end = base + lines->files_len; |
| 140 | |
| 141 | for (int64_t i = 0; i < want; i++) { |
| 142 | while (base < end && *base) |
| 143 | base++; |
| 144 | |
| 145 | if (base >= end) |
| 146 | return NULL; |
| 147 | |
| 148 | base++; /* past the NUL */ |
| 149 | } |
| 150 | |
| 151 | return (base < end) ? base : NULL; |
| 152 | } |
| 153 | |
| 154 | static const char *find_line(uint64_t addr, uint32_t *out_line) { |
| 155 | const struct kernel_lines_hdr *lines = lines_header(); |
| 156 | |
| 157 | if (out_line) |
| 158 | *out_line = 0; |
| 159 | |
| 160 | if (!lines) |
| 161 | return NULL; |
| 162 | |
| 163 | const uint8_t *p = (const uint8_t *) lines + lines->stream_off; |
| 164 | const uint8_t *end = p + lines->stream_len; |
| 165 | |
| 166 | uint64_t cur = lines->base_addr; |
| 167 | int64_t file = 0, line = 0; |
| 168 | int64_t best_file = -1, best_line = 0; |
| 169 | bool found = false; |
| 170 | |
| 171 | for (uint32_t i = 0; i < lines->count && p < end; i++) { |
| 172 | cur += uleb_next(p: &p, end); |
| 173 | file += unzigzag(v: uleb_next(p: &p, end)); |
| 174 | line += unzigzag(v: uleb_next(p: &p, end)); |
| 175 | |
| 176 | if (cur > addr) |
| 177 | break; |
| 178 | |
| 179 | best_file = file; |
| 180 | best_line = line; |
| 181 | found = true; |
| 182 | } |
| 183 | |
| 184 | if (!found || best_line <= 0) |
| 185 | return NULL; |
| 186 | |
| 187 | const char *name = lines_file_name(lines, want: best_file); |
| 188 | if (!name) |
| 189 | return NULL; |
| 190 | |
| 191 | if (out_line) |
| 192 | *out_line = (uint32_t) best_line; |
| 193 | |
| 194 | return name; |
| 195 | } |
| 196 | |
| 197 | static void k_printf_from_log(const char *fmt, const uint64_t *args, |
| 198 | uint8_t nargs, void (*print)(const char *, ...)) { |
| 199 | switch (nargs) { |
| 200 | case 0: print(fmt); break; |
| 201 | case 1: print(fmt, args[0]); break; |
| 202 | case 2: print(fmt, args[0], args[1]); break; |
| 203 | case 3: print(fmt, args[0], args[1], args[2]); break; |
| 204 | case 4: print(fmt, args[0], args[1], args[2], args[3]); break; |
| 205 | case 5: print(fmt, args[0], args[1], args[2], args[3], args[4]); break; |
| 206 | case 6: |
| 207 | print(fmt, args[0], args[1], args[2], args[3], args[4], args[5]); |
| 208 | break; |
| 209 | case 7: |
| 210 | print(fmt, args[0], args[1], args[2], args[3], args[4], args[5], |
| 211 | args[6]); |
| 212 | break; |
| 213 | case 8: |
| 214 | print(fmt, args[0], args[1], args[2], args[3], args[4], args[5], |
| 215 | args[6], args[7]); |
| 216 | break; |
| 217 | default: print("<invalid nargs>" ); |
| 218 | } |
| 219 | } |
| 220 | |
| 221 | static const char *log_level_to_str(enum log_level l) { |
| 222 | switch (l) { |
| 223 | case LOG_TRACE: return "trace" ; |
| 224 | case LOG_DEBUG: return "debug" ; |
| 225 | case LOG_INFO: return "info" ; |
| 226 | case LOG_WARN: return "warn" ; |
| 227 | case LOG_ERROR: return "error" ; |
| 228 | default: return "unknown" ; |
| 229 | } |
| 230 | } |
| 231 | |
| 232 | static void snprintf_from_log(char *buf, size_t size, const char *fmt, |
| 233 | const uint64_t *args, uint8_t nargs) { |
| 234 | if (!fmt) { |
| 235 | buf[0] = '\0'; |
| 236 | return; |
| 237 | } |
| 238 | switch (nargs) { |
| 239 | case 0: snprintf(buffer: buf, buffer_len: size, format: "%s" , fmt); break; |
| 240 | case 1: snprintf(buffer: buf, buffer_len: size, format: fmt, args[0]); break; |
| 241 | case 2: snprintf(buffer: buf, buffer_len: size, format: fmt, args[0], args[1]); break; |
| 242 | case 3: snprintf(buffer: buf, buffer_len: size, format: fmt, args[0], args[1], args[2]); break; |
| 243 | case 4: snprintf(buffer: buf, buffer_len: size, format: fmt, args[0], args[1], args[2], args[3]); break; |
| 244 | case 5: |
| 245 | snprintf(buffer: buf, buffer_len: size, format: fmt, args[0], args[1], args[2], args[3], args[4]); |
| 246 | break; |
| 247 | case 6: |
| 248 | snprintf(buffer: buf, buffer_len: size, format: fmt, args[0], args[1], args[2], args[3], args[4], |
| 249 | args[5]); |
| 250 | break; |
| 251 | case 7: |
| 252 | snprintf(buffer: buf, buffer_len: size, format: fmt, args[0], args[1], args[2], args[3], args[4], |
| 253 | args[5], args[6]); |
| 254 | break; |
| 255 | case 8: |
| 256 | snprintf(buffer: buf, buffer_len: size, format: fmt, args[0], args[1], args[2], args[3], args[4], |
| 257 | args[5], args[6], args[7]); |
| 258 | break; |
| 259 | default: snprintf(buffer: buf, buffer_len: size, format: "<invalid nargs>" ); break; |
| 260 | } |
| 261 | } |
| 262 | |
| 263 | static void log_emit_ndjson_record(const struct log_site *site, |
| 264 | const struct log_record *rec) { |
| 265 | if (!ndjson_carrier_online()) |
| 266 | return; |
| 267 | |
| 268 | char msg_buf[256]; |
| 269 | kassert(rec->fmt); |
| 270 | snprintf_from_log(buf: msg_buf, size: sizeof(msg_buf), fmt: rec->fmt, args: rec->args, |
| 271 | nargs: rec->nargs); |
| 272 | |
| 273 | ndjson_emit(log_message, .site = site->name ? site->name : "unknown" , |
| 274 | .level = log_level_to_str(rec->level), .msg = msg_buf, |
| 275 | .file = rec->caller_file, .line = (uint64_t) rec->caller_line, |
| 276 | .func = rec->caller_fn); |
| 277 | } |
| 278 | |
| 279 | static void log_dump_record(const struct log_site *site, |
| 280 | const struct log_record *rec, |
| 281 | const struct log_dump_options opts, |
| 282 | void (*print)(const char *f, ...)) { |
| 283 | size_t sec = MS_TO_SECONDS(rec->timestamp); |
| 284 | size_t msec = rec->timestamp % 1000; |
| 285 | if (sec == 0 && msec == 0) { |
| 286 | print("[X.XXX] %s%s%s: " , log_level_color(l: rec->level), site->name, |
| 287 | ANSI_RESET); |
| 288 | } else { |
| 289 | if (!rec->handle->print) { |
| 290 | print("[%llu.%03llu] %s%s%s: " , sec, msec, |
| 291 | log_level_color(l: rec->level), site->name, ANSI_RESET); |
| 292 | } else { |
| 293 | rec->handle->print(site, rec, print); |
| 294 | } |
| 295 | } |
| 296 | |
| 297 | if (opts.show_cpu) |
| 298 | print("cpu=%u " , rec->cpu); |
| 299 | |
| 300 | if (opts.show_tid) |
| 301 | print("tid=%u " , rec->tid); |
| 302 | |
| 303 | if (opts.show_irql) |
| 304 | print("irql=%d " , rec->logged_at_irql); |
| 305 | |
| 306 | /* message */ |
| 307 | kassert(rec->fmt); |
| 308 | k_printf_from_log(fmt: rec->fmt, args: rec->args, nargs: rec->nargs, print); |
| 309 | |
| 310 | if (opts.show_caller) { |
| 311 | print(" <+ at %s()" , rec->caller_fn); |
| 312 | } |
| 313 | |
| 314 | if (!(rec->handle->flags & LOG_HANDLE_NO_NEWLINE)) |
| 315 | print("\n" ); |
| 316 | } |
| 317 | |
| 318 | static void log_dump_record_locked(const struct log_site *site, |
| 319 | const struct log_record *rec, |
| 320 | const struct log_dump_options opts) { |
| 321 | enum irql irql = printf_lock(); |
| 322 | log_dump_record(site, rec, opts, print: printf_unlocked); |
| 323 | printf_unlock(i: irql); |
| 324 | } |
| 325 | |
| 326 | static inline bool log_ringbuf_try_enqueue(struct log_site *site, |
| 327 | struct log_ringbuf *rb, |
| 328 | const struct log_record *rec) { |
| 329 | uint64_t pos; |
| 330 | struct log_ring_slot *slot; |
| 331 | |
| 332 | while (true) { |
| 333 | pos = atomic_load_explicit(&rb->head, memory_order_relaxed); |
| 334 | slot = &rb->slots[pos % site->capacity]; |
| 335 | |
| 336 | uint64_t seq = atomic_load_explicit(&slot->seq, memory_order_acquire); |
| 337 | int64_t diff = (int64_t) seq - (int64_t) pos; |
| 338 | |
| 339 | if (diff == 0) { |
| 340 | if (atomic_compare_exchange_weak_explicit(&rb->head, &pos, pos + 1, |
| 341 | memory_order_acq_rel, |
| 342 | memory_order_relaxed)) { |
| 343 | |
| 344 | slot->rec = *rec; |
| 345 | |
| 346 | atomic_store_explicit(&slot->seq, pos + 1, |
| 347 | memory_order_release); |
| 348 | return true; |
| 349 | } |
| 350 | } else if (diff < 0) { |
| 351 | return false; |
| 352 | } |
| 353 | } |
| 354 | } |
| 355 | |
| 356 | static inline bool log_ringbuf_try_dequeue(struct log_site *site, |
| 357 | struct log_ringbuf *rb, |
| 358 | struct log_record *out) { |
| 359 | uint64_t pos; |
| 360 | struct log_ring_slot *slot; |
| 361 | |
| 362 | while (true) { |
| 363 | pos = atomic_load_explicit(&rb->tail, memory_order_relaxed); |
| 364 | slot = &rb->slots[pos % site->capacity]; |
| 365 | |
| 366 | uint64_t seq = atomic_load_explicit(&slot->seq, memory_order_acquire); |
| 367 | int64_t diff = (int64_t) seq - (int64_t) (pos + 1); |
| 368 | |
| 369 | if (diff == 0) { |
| 370 | if (atomic_compare_exchange_weak_explicit(&rb->tail, &pos, pos + 1, |
| 371 | memory_order_acq_rel, |
| 372 | memory_order_relaxed)) { |
| 373 | |
| 374 | *out = slot->rec; |
| 375 | |
| 376 | atomic_store_explicit(&slot->seq, pos + site->capacity, |
| 377 | memory_order_release); |
| 378 | return true; |
| 379 | } |
| 380 | } else if (diff < 0) { |
| 381 | return false; |
| 382 | } |
| 383 | } |
| 384 | } |
| 385 | |
| 386 | static bool log_ringbuf_force_enqueue(struct log_site *site, |
| 387 | struct log_ringbuf *rb, |
| 388 | const struct log_record *rec) { |
| 389 | struct log_record dummy; |
| 390 | log_ringbuf_try_dequeue(site, rb, out: &dummy); |
| 391 | return log_ringbuf_try_enqueue(site, rb, rec); |
| 392 | } |
| 393 | |
| 394 | void log_dump_site_with_opts(struct log_site *site, |
| 395 | struct log_dump_options opts) { |
| 396 | struct log_record rec; |
| 397 | if (!site || !log_site_get(site)) |
| 398 | return; |
| 399 | |
| 400 | enum irql irql = printf_lock(); |
| 401 | while (log_ringbuf_try_dequeue(site, rb: &site->rb, out: &rec)) { |
| 402 | if (rec.level < opts.min_level) |
| 403 | continue; |
| 404 | |
| 405 | if (site->dropped) { |
| 406 | printf_unlocked(format: "!! dropped %u log records !!\n" , site->dropped); |
| 407 | } |
| 408 | |
| 409 | log_dump_record(site, rec: &rec, opts, print: printf_unlocked); |
| 410 | } |
| 411 | printf_unlock(i: irql); |
| 412 | |
| 413 | log_site_put(site); |
| 414 | } |
| 415 | |
| 416 | void log_dump_site_default(struct log_site *site) { |
| 417 | if (!site || !log_site_get(site)) |
| 418 | return; |
| 419 | |
| 420 | log_dump_site_with_opts(site, LOG_DUMP_DEFAULT); |
| 421 | log_site_put(site); |
| 422 | } |
| 423 | |
| 424 | void log_dump_site(struct log_site *site) { |
| 425 | log_dump_site_with_opts(site, opts: site->dump_opts); |
| 426 | } |
| 427 | |
| 428 | void log_emit_internal(struct log_site *site, struct log_handle *handle, |
| 429 | enum log_level ll, const char *func, const char *file, |
| 430 | int32_t line, uintptr_t ip, uint8_t narg, char *fmt, |
| 431 | ...) { |
| 432 | if (!site || !log_site_get(site)) |
| 433 | return; |
| 434 | |
| 435 | enum log_level level = ll; |
| 436 | struct log_record rec = {0}; |
| 437 | rec.handle = handle; |
| 438 | rec.level = level; |
| 439 | |
| 440 | if (site->flags & LOG_SITE_DUP_MESSAGES) { |
| 441 | strncpy(dest: (char *) rec.fmt, src: fmt, n: site->msg_max_len - 1); |
| 442 | } else { |
| 443 | rec.fmt = fmt; |
| 444 | } |
| 445 | |
| 446 | rec.caller_pc = ip; |
| 447 | rec.caller_fn = (char *) func; |
| 448 | rec.caller_file = (char *) file; |
| 449 | rec.caller_line = line; |
| 450 | |
| 451 | /* pack args */ |
| 452 | va_list ap; |
| 453 | va_start(ap, fmt); |
| 454 | for (int i = 0; i < narg && i < 8; i++) { |
| 455 | rec.args[i] = va_arg(ap, uint64_t); |
| 456 | rec.nargs++; |
| 457 | } |
| 458 | va_end(ap); |
| 459 | |
| 460 | struct log_dump_options dopts = site->dump_opts; |
| 461 | |
| 462 | BOOTSTAGE_IF_LT(BOOTSTAGE_LATE) { |
| 463 | if (log_handle_should_print(h: handle, s: site, level)) |
| 464 | return log_dump_record(site, rec: &rec, opts: dopts, print: printf); |
| 465 | } |
| 466 | |
| 467 | if (site->flags & LOG_SITE_NO_IRQ && irq_in_interrupt()) |
| 468 | return; |
| 469 | |
| 470 | if (!log_site_enabled(ss: site, level)) |
| 471 | return; |
| 472 | |
| 473 | rec.timestamp = time_get_ms(); |
| 474 | rec.cpu = smp_id_raw(); /* Merely a snapshot */ |
| 475 | rec.tid = thread_get_current()->id; |
| 476 | rec.logged_at_irql = irql_get(); |
| 477 | |
| 478 | if (irq_in_interrupt()) |
| 479 | rec.flags |= LOG_REC_FROM_IRQ; |
| 480 | |
| 481 | if (handle->flags & LOG_HANDLE_ONCE) { |
| 482 | if (atomic_fetch_add(&handle->seen_internal, 1) != 0) |
| 483 | return; |
| 484 | } |
| 485 | |
| 486 | if (handle->flags & LOG_HANDLE_RATELIMIT) { |
| 487 | uint64_t now = rec.timestamp; |
| 488 | uint64_t last = atomic_load(&handle->last_ts_internal); |
| 489 | |
| 490 | if (now - last < 100) |
| 491 | return; |
| 492 | |
| 493 | atomic_store(&handle->last_ts_internal, now); |
| 494 | } |
| 495 | |
| 496 | bool queued = log_ringbuf_try_enqueue(site, rb: &site->rb, rec: &rec); |
| 497 | |
| 498 | if (!queued) { |
| 499 | if (handle->flags & LOG_HANDLE_IMPORTANT) { |
| 500 | if (site->flags & LOG_SITE_DROP_OLD) { |
| 501 | queued = log_ringbuf_force_enqueue(site, rb: &site->rb, rec: &rec); |
| 502 | } else if (!irq_in_interrupt()) { |
| 503 | for (int i = 0; i < LOG_IMPORTANT_RETRY; i++) { |
| 504 | if (log_ringbuf_try_enqueue(site, rb: &site->rb, rec: &rec)) { |
| 505 | queued = true; |
| 506 | break; |
| 507 | } |
| 508 | cpu_relax(); |
| 509 | } |
| 510 | } |
| 511 | |
| 512 | if (!queued) { |
| 513 | /* last-resort visibility */ |
| 514 | log_dump_record_locked(site, rec: &rec, opts: dopts); |
| 515 | } |
| 516 | } else { |
| 517 | site->dropped++; |
| 518 | } |
| 519 | } |
| 520 | |
| 521 | if (log_handle_should_print(h: handle, s: site, level)) { |
| 522 | log_dump_record_locked(site, rec: &rec, opts: dopts); |
| 523 | } |
| 524 | |
| 525 | if (site->flags & LOG_SITE_NDJSON) { |
| 526 | log_emit_ndjson_record(site, rec: &rec); |
| 527 | } |
| 528 | |
| 529 | if ((ll & LOG_HANDLE_PANIC) && level >= LOG_ERROR) { |
| 530 | log_dump_all(); |
| 531 | debug_print_stack(); |
| 532 | panic("fatal log event" ); |
| 533 | } |
| 534 | |
| 535 | log_site_put(site); |
| 536 | } |
| 537 | |
| 538 | void log_sites_init(void) { |
| 539 | log_global.initialized = true; |
| 540 | locked_list_init(ll: &log_global.list, LOCKED_LIST_INIT_NORMAL); |
| 541 | |
| 542 | for (struct log_site *s = __skernel_log_sites; s < __ekernel_log_sites; |
| 543 | s++) { |
| 544 | INIT_LIST_HEAD(list: &s->list); |
| 545 | refcount_init(rc: &s->refcount, val: 1); |
| 546 | struct log_ringbuf *lrb = &s->rb; |
| 547 | kassert(s->capacity); |
| 548 | lrb->slots = kmalloc_or_die(sizeof(struct log_ring_slot) * s->capacity, |
| 549 | ALLOC_FLAGS_ZERO); |
| 550 | |
| 551 | for (size_t i = 0; i < s->capacity; i++) { |
| 552 | atomic_store_explicit(&lrb->slots[i].seq, i, memory_order_release); |
| 553 | } |
| 554 | |
| 555 | locked_list_add(ll: &log_global.list, lh: &s->list); |
| 556 | } |
| 557 | } |
| 558 | |
| 559 | void log_dump_all(void) { |
| 560 | enum irql irql = spin_lock_irq_disable(&log_global.list.lock); |
| 561 | |
| 562 | struct log_site *site; |
| 563 | list_for_each_entry(site, &log_global.list.list, list) { |
| 564 | log_dump_site(site); |
| 565 | } |
| 566 | |
| 567 | spin_unlock(&log_global.list.lock, irql); |
| 568 | } |
| 569 | |
| 570 | void log_dump_panic(void) { |
| 571 | |
| 572 | struct log_site *site; |
| 573 | list_for_each_entry(site, &log_global.list.list, list) { |
| 574 | if (site->flags & LOG_SITE_PANIC_VISIBLE) |
| 575 | log_dump_site(site); |
| 576 | } |
| 577 | } |
| 578 | |
| 579 | void log_site_free(struct log_site *site) { |
| 580 | locked_list_del(ll: &log_global.list, lh: &site->list); |
| 581 | kfree(site->rb.slots); |
| 582 | kfree(site->name); |
| 583 | kfree_aligned(site, _Alignof(struct log_site)); |
| 584 | } |
| 585 | |
| 586 | struct log_site *log_site_create(struct log_site_options opts) { |
| 587 | struct log_site *ret = kmalloc_aligned( |
| 588 | sizeof(struct log_site), _Alignof(struct log_site), ALLOC_FLAGS_ZERO); |
| 589 | if (!ret) |
| 590 | return NULL; |
| 591 | |
| 592 | ret->name = strdup(str: opts.name); |
| 593 | if (!ret->name) |
| 594 | goto err; |
| 595 | |
| 596 | struct log_ring_slot *slots = |
| 597 | kmalloc(sizeof(struct log_ring_slot) * opts.capacity, ALLOC_FLAGS_ZERO); |
| 598 | if (!slots) |
| 599 | goto err; |
| 600 | |
| 601 | if (opts.flags & LOG_SITE_DUP_MESSAGES) { |
| 602 | size_t len = kassert(opts.msg_max_len); |
| 603 | for (size_t i = 0; i < opts.capacity; i++) { |
| 604 | slots[i].shadow_buf = kmalloc(len, ALLOC_FLAGS_ZERO); |
| 605 | if (!slots->shadow_buf) { |
| 606 | for (size_t j = 0; j < i; j++) { |
| 607 | kfree(slots[j].shadow_buf); |
| 608 | } |
| 609 | |
| 610 | goto err; |
| 611 | } |
| 612 | |
| 613 | slots[i].rec.fmt = slots[i].shadow_buf; |
| 614 | } |
| 615 | } |
| 616 | |
| 617 | ret->msg_max_len = opts.msg_max_len; |
| 618 | ret->dump_opts = opts.dump_opts; |
| 619 | ret->enabled_mask = opts.enabled_mask; |
| 620 | ret->capacity = opts.capacity; |
| 621 | ret->rb.slots = slots; |
| 622 | refcount_init(rc: &ret->refcount, val: 1); |
| 623 | ret->dropped = 0; |
| 624 | ret->flags = opts.flags; |
| 625 | INIT_LIST_HEAD(list: &ret->list); |
| 626 | for (size_t i = 0; i < opts.capacity; i++) { |
| 627 | atomic_store_explicit(&slots[i].seq, i, memory_order_release); |
| 628 | } |
| 629 | |
| 630 | locked_list_add(ll: &log_global.list, lh: &ret->list); |
| 631 | |
| 632 | return ret; |
| 633 | |
| 634 | err: |
| 635 | |
| 636 | if (ret) { |
| 637 | kfree(ret->rb.slots); |
| 638 | kfree(ret->name); |
| 639 | } |
| 640 | |
| 641 | kfree_aligned(ret, _Alignof(struct log_site)); |
| 642 | return NULL; |
| 643 | } |
| 644 | |
| 645 | static bool stack_addr_readable(uint64_t addr) { |
| 646 | return vmm_get_phys(PAGE_ALIGN_DOWN(addr), VMM_FLAG_NONE) != (uintptr_t) -1; |
| 647 | } |
| 648 | |
| 649 | /* Frame holds caller's saved rbp at [0] and ret addr at [1], so both |
| 650 | * qwords have to be there */ |
| 651 | static bool stack_frame_readable(uint64_t frame) { |
| 652 | if (!frame || (frame & (sizeof(uint64_t) - 1))) |
| 653 | return false; |
| 654 | |
| 655 | return stack_addr_readable(addr: frame) && |
| 656 | stack_addr_readable(addr: frame + sizeof(uint64_t)); |
| 657 | } |
| 658 | |
| 659 | static bool stack_addr_is_text(uint64_t addr) { |
| 660 | return addr >= (uint64_t) &__stext && addr < (uint64_t) &__etext; |
| 661 | } |
| 662 | |
| 663 | /* Use the rbp chain that -fno-omit-frame-pointer builds, and collect |
| 664 | * them all into `entries`, returning the number of entries found */ |
| 665 | size_t stack_unwind(uint64_t frame, uint64_t *entries, size_t max) { |
| 666 | size_t nr = 0; |
| 667 | |
| 668 | if (max > STACK_TRACE_MAX_DEPTH) |
| 669 | max = STACK_TRACE_MAX_DEPTH; |
| 670 | |
| 671 | while (nr < max) { |
| 672 | if (!stack_frame_readable(frame)) |
| 673 | break; |
| 674 | |
| 675 | uint64_t next = ((const uint64_t *) frame)[0]; |
| 676 | uint64_t ret = ((const uint64_t *) frame)[1]; |
| 677 | |
| 678 | if (!stack_addr_is_text(addr: ret)) |
| 679 | break; |
| 680 | |
| 681 | if (entries) |
| 682 | entries[nr] = ret; |
| 683 | |
| 684 | nr++; |
| 685 | if (next <= frame) |
| 686 | break; |
| 687 | |
| 688 | frame = next; |
| 689 | } |
| 690 | |
| 691 | return nr; |
| 692 | } |
| 693 | |
| 694 | const char *debug_symbolize(uint64_t addr, uint64_t *out_off) { |
| 695 | uint64_t base = 0; |
| 696 | const char *sym = find_symbol(addr, out_sym_addr: &base); |
| 697 | |
| 698 | if (out_off) |
| 699 | *out_off = sym ? addr - base : 0; |
| 700 | |
| 701 | return sym; |
| 702 | } |
| 703 | |
| 704 | const char *debug_line_for(uint64_t addr, uint32_t *out_line) { |
| 705 | return find_line(addr, out_line); |
| 706 | } |
| 707 | |
| 708 | bool debug_syms_present(void) { |
| 709 | return syms_header() != NULL; |
| 710 | } |
| 711 | |
| 712 | void debug_print_stack_trace(const uint64_t *entries, size_t nr) { |
| 713 | if (!nr) { |
| 714 | printf(format: " <no kernel frames found>\n" ); |
| 715 | return; |
| 716 | } |
| 717 | |
| 718 | syms_warn_if_missing(); |
| 719 | |
| 720 | for (size_t i = 0; i < nr; i++) { |
| 721 | uint64_t sym_addr; |
| 722 | const char *sym = find_symbol(addr: entries[i], out_sym_addr: &sym_addr); |
| 723 | |
| 724 | if (sym) { |
| 725 | printf(format: " #%-2zu [0x%016lx] %s+0x%lx\n" , i, entries[i], sym, |
| 726 | entries[i] - sym_addr); |
| 727 | } else { |
| 728 | printf(format: " #%-2zu [0x%016lx] <unknown>\n" , i, entries[i]); |
| 729 | } |
| 730 | |
| 731 | uint32_t line; |
| 732 | const char *file = find_line(addr: entries[i] - 1, out_line: &line); |
| 733 | |
| 734 | if (file) |
| 735 | printf(format: " at %s:%u\n" , file, line); |
| 736 | } |
| 737 | } |
| 738 | |
| 739 | void debug_print_stack(void) { |
| 740 | uint64_t entries[STACK_TRACE_MAX_DEPTH]; |
| 741 | |
| 742 | size_t nr = stack_unwind(frame: (uint64_t) __builtin_frame_address(0), entries, |
| 743 | max: sizeof(entries) / sizeof(*entries)); |
| 744 | |
| 745 | debug_print_stack_trace(entries, nr); |
| 746 | } |
| 747 | |
| 748 | void debug_print_memory(void *addr, uint64_t size) { |
| 749 | uint8_t *ptr = (uint8_t *) addr; |
| 750 | printf(format: "Memory at %p:\n" , (uint64_t) addr); |
| 751 | for (uint64_t i = 0; i < size; i++) { |
| 752 | if (i % 16 == 0) { |
| 753 | if (i != 0) |
| 754 | printf(format: "\n" ); |
| 755 | printf(format: "%p: " , (uint64_t) (ptr + i)); |
| 756 | } |
| 757 | printf(format: "%02x " , ptr[i]); |
| 758 | } |
| 759 | printf(format: "\n" ); |
| 760 | } |
| 761 | |
| 762 | void debug_print_stack_from(uint64_t *start, size_t max_scan) { |
| 763 | int hits = 0; |
| 764 | uint8_t *last_checked_page = NULL; |
| 765 | |
| 766 | if (!max_scan) |
| 767 | max_scan = 64 * 1024; |
| 768 | |
| 769 | syms_warn_if_missing(); |
| 770 | |
| 771 | printf(format: "Stack unwind from %p:\n" , (uint64_t) start); |
| 772 | |
| 773 | for (size_t offset = 0; offset < max_scan; offset += sizeof(uint64_t)) { |
| 774 | uint8_t *addr = (uint8_t *) start + offset; |
| 775 | uint8_t *page_base = (uint8_t *) PAGE_ALIGN_DOWN(addr); |
| 776 | |
| 777 | if (page_base != last_checked_page) { |
| 778 | if (vmm_get_phys((vaddr_t) page_base, VMM_FLAG_NONE) == |
| 779 | (uintptr_t) -1) |
| 780 | break; |
| 781 | last_checked_page = page_base; |
| 782 | } |
| 783 | |
| 784 | uint64_t val = *(uint64_t *) addr; |
| 785 | |
| 786 | if (val >= 0xffffffff80000000ULL && val <= 0xffffffffffffffffULL) { |
| 787 | uint64_t sym_addr; |
| 788 | const char *sym = find_symbol(addr: val, out_sym_addr: &sym_addr); |
| 789 | if (sym) { |
| 790 | printf(format: " [0x%016lx] %s+0x%lx (sp=0x%016lx)\n" , val, sym, |
| 791 | val - sym_addr, (uint64_t) addr); |
| 792 | hits++; |
| 793 | } |
| 794 | } |
| 795 | } |
| 796 | |
| 797 | if (hits == 0) |
| 798 | printf(format: " <no kernel symbols found>\n" ); |
| 799 | } |
| 800 | |