1#include <bootstage_condition.h>
2#include <console/printf.h>
3#include <linker/symbol_table.h>
4#include <log.h>
5#include <mem/alloc_or_die.h>
6#include <mem/vmm.h>
7#include <sch/sched.h>
8#include <smp/core.h>
9#include <stdarg.h>
10#include <stddef.h>
11#include <stdint.h>
12#include <string.h>
13#include <structures/locked_list.h>
14#include <thread/thread.h>
15#include <time/time.h>
16
17#define LOG_IMPORTANT_RETRY 32
18LOG_SITE_DECLARE(global, .flags = LOG_SITE_DEFAULT,
19 .capacity = LOG_SITE_CAPACITY_DEFAULT,
20 .dump_opts = LOG_DUMP_CONSOLE, .enabled_mask = LOG_SITE_ALL);
21
22LOG_HANDLE_DECLARE(global, .flags = LOG_PRINT);
23
24struct log_globals {
25 struct locked_list list;
26};
27
28struct log_globals log_global = {0};
29
30static const char *find_symbol(uint64_t addr, uint64_t *out_sym_addr) {
31 const char *result = NULL;
32 uint64_t best = 0;
33
34 for (uint64_t i = 0; i < syms_len; i++) {
35 if (syms[i].addr <= addr && syms[i].addr > best) {
36 best = syms[i].addr;
37 result = syms[i].name;
38 }
39 }
40
41 if (out_sym_addr)
42 *out_sym_addr = best;
43
44 return result;
45}
46
47static void k_printf_from_log(const char *fmt, const uint64_t *args,
48 uint8_t nargs, void (*print)(const char *, ...)) {
49 switch (nargs) {
50 case 0: print(fmt); break;
51 case 1: print(fmt, args[0]); break;
52 case 2: print(fmt, args[0], args[1]); break;
53 case 3: print(fmt, args[0], args[1], args[2]); break;
54 case 4: print(fmt, args[0], args[1], args[2], args[3]); break;
55 case 5: print(fmt, args[0], args[1], args[2], args[3], args[4]); break;
56 case 6:
57 print(fmt, args[0], args[1], args[2], args[3], args[4], args[5]);
58 break;
59 case 7:
60 print(fmt, args[0], args[1], args[2], args[3], args[4], args[5],
61 args[6]);
62 break;
63 case 8:
64 print(fmt, args[0], args[1], args[2], args[3], args[4], args[5],
65 args[6], args[7]);
66 break;
67 default: print("<invalid nargs>");
68 }
69}
70
71static void log_dump_record(const struct log_site *site,
72 const struct log_record *rec,
73 const struct log_dump_options opts,
74 void (*print)(const char *f, ...)) {
75 size_t sec = MS_TO_SECONDS(rec->timestamp);
76 size_t msec = rec->timestamp % 1000;
77 if (sec == 0 && msec == 0) {
78 print("[X.XXX] %s%s%s: ", log_level_color(l: rec->level), site->name,
79 ANSI_RESET);
80 } else {
81 print("[%llu.%03llu] %s%s%s: ", sec, msec, log_level_color(l: rec->level),
82 site->name, ANSI_RESET);
83 }
84
85 if (opts.show_cpu)
86 print("cpu=%u ", rec->cpu);
87
88 if (opts.show_tid)
89 print("tid=%u ", rec->tid);
90
91 if (opts.show_irql)
92 print("irql=%d ", rec->logged_at_irql);
93
94 /* message */
95 if (opts.show_args && rec->fmt) {
96 k_printf_from_log(fmt: rec->fmt, args: rec->args, nargs: rec->nargs, print);
97 } else if (rec->handle && rec->handle->msg) {
98 print("%s", rec->handle->msg);
99 }
100
101 if (opts.show_caller) {
102 print(" <+ at %s()", rec->caller_fn);
103 }
104
105 if (!(rec->handle->flags & LOG_NO_NEWLINE))
106 print("\n");
107}
108
109static void log_dump_record_locked(const struct log_site *site,
110 const struct log_record *rec,
111 const struct log_dump_options opts) {
112 enum irql irql = printf_lock();
113 log_dump_record(site, rec, opts, print: printf_unlocked);
114 printf_unlock(i: irql);
115}
116
117static inline bool log_ringbuf_try_enqueue(struct log_site *site,
118 struct log_ringbuf *rb,
119 const struct log_record *rec) {
120 uint64_t pos;
121 struct log_ring_slot *slot;
122
123 while (true) {
124 pos = atomic_load_explicit(&rb->head, memory_order_relaxed);
125 slot = &rb->slots[pos % site->capacity];
126
127 uint64_t seq = atomic_load_explicit(&slot->seq, memory_order_acquire);
128 int64_t diff = (int64_t) seq - (int64_t) pos;
129
130 if (diff == 0) {
131 if (atomic_compare_exchange_weak_explicit(&rb->head, &pos, pos + 1,
132 memory_order_acq_rel,
133 memory_order_relaxed)) {
134
135 slot->rec = *rec;
136
137 atomic_store_explicit(&slot->seq, pos + 1,
138 memory_order_release);
139 return true;
140 }
141 } else if (diff < 0) {
142 return false;
143 }
144 }
145}
146
147static inline bool log_ringbuf_try_dequeue(struct log_site *site,
148 struct log_ringbuf *rb,
149 struct log_record *out) {
150 uint64_t pos;
151 struct log_ring_slot *slot;
152
153 while (true) {
154 pos = atomic_load_explicit(&rb->tail, memory_order_relaxed);
155 slot = &rb->slots[pos % site->capacity];
156
157 uint64_t seq = atomic_load_explicit(&slot->seq, memory_order_acquire);
158 int64_t diff = (int64_t) seq - (int64_t) (pos + 1);
159
160 if (diff == 0) {
161 if (atomic_compare_exchange_weak_explicit(&rb->tail, &pos, pos + 1,
162 memory_order_acq_rel,
163 memory_order_relaxed)) {
164
165 *out = slot->rec;
166
167 atomic_store_explicit(&slot->seq, pos + site->capacity,
168 memory_order_release);
169 return true;
170 }
171 } else if (diff < 0) {
172 return false;
173 }
174 }
175}
176
177static bool log_ringbuf_force_enqueue(struct log_site *site,
178 struct log_ringbuf *rb,
179 const struct log_record *rec) {
180 struct log_record dummy;
181 log_ringbuf_try_dequeue(site, rb, out: &dummy);
182 return log_ringbuf_try_enqueue(site, rb, rec);
183}
184
185void log_dump_site_with_opts(struct log_site *site,
186 struct log_dump_options opts) {
187 struct log_record rec;
188 if (!site || !log_site_get(site))
189 return;
190
191 enum irql irql = printf_lock();
192 while (log_ringbuf_try_dequeue(site, rb: &site->rb, out: &rec)) {
193 if (rec.level < opts.min_level)
194 continue;
195
196 if (site->dropped) {
197 printf_unlocked(format: "!! dropped %u log records !!\n", site->dropped);
198 }
199
200 log_dump_record(site, rec: &rec, opts, print: printf_unlocked);
201 }
202 printf_unlock(i: irql);
203
204 log_site_put(site);
205}
206
207void log_dump_site_default(struct log_site *site) {
208 if (!site || !log_site_get(site))
209 return;
210
211 log_dump_site_with_opts(site, LOG_DUMP_DEFAULT);
212 log_site_put(site);
213}
214
215void log_dump_site(struct log_site *site) {
216 log_dump_site_with_opts(site, opts: site->dump_opts);
217}
218
219void log_emit_internal(struct log_site *site, struct log_handle *handle,
220 enum log_level ll, const char *func, const char *file,
221 int32_t line, uintptr_t ip, uint8_t narg, char *fmt,
222 ...) {
223 if (!site || !log_site_get(site))
224 return;
225
226 enum log_level level = ll;
227 struct log_record rec = {0};
228 rec.handle = handle;
229 rec.level = level;
230 rec.fmt = fmt;
231 rec.caller_pc = ip;
232 rec.caller_fn = (char *) func;
233 rec.caller_file = (char *) file;
234 rec.caller_line = line;
235
236 /* pack args */
237 va_list ap;
238 va_start(ap, fmt);
239 for (int i = 0; i < narg && i < 8; i++) {
240 rec.args[i] = va_arg(ap, uint64_t);
241 rec.nargs++;
242 }
243 va_end(ap);
244
245 struct log_dump_options dopts = site->dump_opts;
246
247 BOOTSTAGE_IF_LT(BOOTSTAGE_LATE) {
248 if (log_handle_should_print(h: handle, s: site, level))
249 return log_dump_record(site, rec: &rec, opts: dopts, print: printf);
250 }
251
252 if (!log_site_accepts(s: site) ||
253 (site->flags & LOG_SITE_NO_IRQ && irq_in_interrupt()))
254 return;
255
256 if (!log_site_enabled(ss: site, level))
257 return;
258
259 rec.timestamp = time_get_ms();
260 rec.cpu = smp_core_id();
261 rec.tid = thread_get_current()->id;
262 rec.logged_at_irql = irql_get();
263
264 if (irq_in_interrupt())
265 rec.flags |= LOG_REC_FROM_IRQ;
266
267 if (handle->flags & LOG_ONCE) {
268 if (atomic_fetch_add(&handle->seen_internal, 1) != 0)
269 return;
270 }
271
272 if (handle->flags & LOG_RATELIMIT) {
273 uint64_t now = rec.timestamp;
274 uint64_t last = atomic_load(&handle->last_ts_internal);
275
276 if (now - last < 100)
277 return;
278
279 atomic_store(&handle->last_ts_internal, now);
280 }
281
282 bool queued = log_ringbuf_try_enqueue(site, rb: &site->rb, rec: &rec);
283
284 if (!queued) {
285 if (handle->flags & LOG_IMPORTANT) {
286 if (site->flags & LOG_SITE_DROP_OLD) {
287 queued = log_ringbuf_force_enqueue(site, rb: &site->rb, rec: &rec);
288 } else if (!irq_in_interrupt()) {
289 for (int i = 0; i < LOG_IMPORTANT_RETRY; i++) {
290 if (log_ringbuf_try_enqueue(site, rb: &site->rb, rec: &rec)) {
291 queued = true;
292 break;
293 }
294 cpu_relax();
295 }
296 }
297
298 if (!queued) {
299 /* last-resort visibility */
300 log_dump_record_locked(site, rec: &rec, opts: dopts);
301 }
302 } else {
303 site->dropped++;
304 }
305 }
306
307 if (log_handle_should_print(h: handle, s: site, level)) {
308 log_dump_record_locked(site, rec: &rec, opts: dopts);
309 }
310
311 if ((ll & LOG_PANIC) && level >= LOG_ERROR) {
312 log_dump_all();
313 debug_print_stack();
314 panic("fatal log event");
315 }
316
317 log_site_put(site);
318}
319
320void log_sites_init(void) {
321 locked_list_init(ll: &log_global.list, LOCKED_LIST_INIT_NORMAL);
322
323 for (struct log_site *s = __skernel_log_sites; s < __ekernel_log_sites;
324 s++) {
325 INIT_LIST_HEAD(list: &s->list);
326 s->enabled = true;
327 refcount_init(rc: &s->refcount, val: 1);
328 struct log_ringbuf *lrb = &s->rb;
329 kassert(s->capacity);
330 lrb->slots = kmalloc_or_die(sizeof(struct log_ring_slot) * s->capacity,
331 ALLOC_FLAGS_ZERO);
332
333 for (size_t i = 0; i < s->capacity; i++) {
334 atomic_store_explicit(&lrb->slots[i].seq, i, memory_order_release);
335 }
336
337 locked_list_add(ll: &log_global.list, lh: &s->list);
338 }
339}
340
341void log_dump_all(void) {
342 enum irql irql = spin_lock_irq_disable(lock: &log_global.list.lock);
343
344 struct log_site *site;
345 list_for_each_entry(site, &log_global.list.list, list) {
346 log_dump_site_default(site);
347 }
348
349 spin_unlock(lock: &log_global.list.lock, old: irql);
350}
351
352void log_site_free(struct log_site *site) {
353 locked_list_del(ll: &log_global.list, lh: &site->list);
354 kfree(site->rb.slots);
355 kfree(site->name);
356 kfree_aligned(site, _Alignof(struct log_site));
357}
358
359struct log_site *log_site_create(struct log_site_options opts) {
360 struct log_site *ret = kmalloc_aligned(
361 sizeof(struct log_site), _Alignof(struct log_site), ALLOC_FLAGS_ZERO);
362 if (!ret)
363 return NULL;
364
365 ret->name = strdup(str: opts.name);
366 if (!ret->name)
367 goto err;
368
369 struct log_ring_slot *slots =
370 kmalloc(sizeof(struct log_ring_slot) * opts.capacity, ALLOC_FLAGS_ZERO);
371 if (!slots)
372 goto err;
373
374 ret->dump_opts = opts.dump_opts;
375 ret->enabled_mask = opts.enabled_mask;
376 ret->capacity = opts.capacity;
377 ret->rb.slots = slots;
378 refcount_init(rc: &ret->refcount, val: 1);
379 ret->dropped = 0;
380 ret->flags = opts.flags;
381 INIT_LIST_HEAD(list: &ret->list);
382 ret->enabled = true;
383 for (size_t i = 0; i < opts.capacity; i++) {
384 atomic_store_explicit(&slots[i].seq, i, memory_order_release);
385 }
386
387 locked_list_add(ll: &log_global.list, lh: &ret->list);
388
389 return ret;
390
391err:
392
393 if (ret) {
394 kfree(ret->rb.slots);
395 kfree(ret->name);
396 }
397
398 kfree_aligned(ret, _Alignof(struct log_site));
399 return NULL;
400}
401
402void debug_print_stack(void) {
403 uint64_t *rsp;
404 asm volatile("mov %%rsp, %0" : "=r"(rsp));
405
406 uint64_t *p = rsp;
407 int hits = 0;
408
409 const size_t MAX_SCAN = 64 * 1024;
410
411 uint8_t *last_checked_page = NULL;
412
413 for (size_t offset = 0; offset < MAX_SCAN; offset += sizeof(uint64_t)) {
414 uint8_t *addr = (uint8_t *) p + offset;
415
416 uint8_t *page_base = (uint8_t *) PAGE_ALIGN_DOWN(addr);
417 if (page_base != last_checked_page) {
418 if (vmm_get_phys((vaddr_t) page_base, VMM_FLAG_NONE) ==
419 (uintptr_t) -1) {
420 break;
421 }
422 last_checked_page = page_base;
423 }
424
425 uint64_t val = *(uint64_t *) addr;
426 if (val >= 0xffffffff80000000ULL && val <= 0xffffffffffffffffULL) {
427 uint64_t sym_addr;
428 const char *sym = find_symbol(addr: val, out_sym_addr: &sym_addr);
429 if (sym) {
430 printf(format: " [0x%016lx] %s+%p (sp=0x%016lx)\n", val, sym,
431 val - sym_addr, (uint64_t) addr);
432 hits++;
433 }
434 }
435 }
436
437 if (hits == 0)
438 printf(format: " <no kernel symbols found>\n");
439}
440
441void debug_print_memory(void *addr, uint64_t size) {
442 uint8_t *ptr = (uint8_t *) addr;
443 printf(format: "Memory at %p:\n", (uint64_t) addr);
444 for (uint64_t i = 0; i < size; i++) {
445 if (i % 16 == 0) {
446 if (i != 0)
447 printf(format: "\n");
448 printf(format: "%p: ", (uint64_t) (ptr + i));
449 }
450 printf(format: "%02x ", ptr[i]);
451 }
452 printf(format: "\n");
453}
454
455void debug_print_stack_from(uint64_t *start, size_t max_scan) {
456 int hits = 0;
457 uint8_t *last_checked_page = NULL;
458
459 if (!max_scan)
460 max_scan = 64 * 1024;
461
462 printf(format: "Stack unwind from %p:\n", (uint64_t) start);
463
464 for (size_t offset = 0; offset < max_scan; offset += sizeof(uint64_t)) {
465 uint8_t *addr = (uint8_t *) start + offset;
466 uint8_t *page_base = (uint8_t *) PAGE_ALIGN_DOWN(addr);
467
468 if (page_base != last_checked_page) {
469 if (vmm_get_phys((vaddr_t) page_base, VMM_FLAG_NONE) ==
470 (uintptr_t) -1)
471 break;
472 last_checked_page = page_base;
473 }
474
475 uint64_t val = *(uint64_t *) addr;
476
477 if (val >= 0xffffffff80000000ULL && val <= 0xffffffffffffffffULL) {
478 uint64_t sym_addr;
479 const char *sym = find_symbol(addr: val, out_sym_addr: &sym_addr);
480 if (sym) {
481 printf(format: " [0x%016lx] %s+0x%lx (sp=0x%016lx)\n", val, sym,
482 val - sym_addr, (uint64_t) addr);
483 hits++;
484 }
485 }
486 }
487
488 if (hits == 0)
489 printf(format: " <no kernel symbols found>\n");
490}
491