// SPDX-License-Identifier: Apache-2.0 // // The kernel log that outlives the kernel. See include/klog.h. // // Two properties are worth reading the code for, because both are easy to // write and easy to get subtly wrong: // // **It takes no lock.** klog_putc() runs inside consputc(), which runs with // cons.lock held on the ordinary path and with interrupts off and every other // CPU spinning on the panic path. A lock here would add a way for the logger // to deadlock the thing it exists to report on, which is the one failure it // must not have. The cost is that two CPUs printing at once can interleave // characters -- which is already true of the console itself, so the log is no // worse than the screen it mirrors. // // **It buffers before it exists.** The region is carved after e820_init(), so // everything printed before that -- the loader's handover, the memory map // itself -- has nowhere to go yet. Dropping it would mean the log is blank for // exactly the part of the boot that is hardest to debug any other way, so // early output goes into a small static array and is flushed into the ring the // moment there is one. #include "types.h" #include "defs.h" #include "memlayout.h" #include "klog.h" #include "sbuf.h" #include "dbg.h" // consputc()'s cursor-movement escape, from kernel/core/console.c. #define BACKSPACE 0x100 static struct klog_hdr *klog; static int recovered; // the buffer held a previous boot when we found it static uint64 prev_bytes; // how much of it that was // Early output, before there is a ring to put it in. One page is enough for // the handful of lines between the first cprintf and klog_init(); anything // past it is dropped rather than overwritten, because the *first* lines of a // boot that died early are the ones worth having. static char early[4096]; static int nearly; static int early_lost; // Line state, kept here rather than derived, so a timestamp is emitted once // per line and not once per write. static int at_line_start = 1; // Over the fields that do not move while a kernel is running -- deliberately // not over head and mark. // // Those two change on every character written, and a sum that covered them // would have to be recomputed on every character too: eight multiplies per // byte of log, for a check whose entire job is to notice that some *other* // program used this memory between two boots. head and mark are validated by // range instead, which catches the same thing without the cost. // // Not a CRC either, for the same reason of proportion: this does not need to // detect a clever corruption, and dragging kernel/fs/schfs's crc32c into core // to do it would be a dependency in the wrong direction. static uint32 checksum(const struct klog_hdr *h) { uint32 s = 0x9e3779b9u; s = s * 31 + h->magic; s = s * 31 + h->version; s = s * 31 + h->size; return s; } static int looks_valid(const struct klog_hdr *h, uint64 bytes) { if (h->magic != KLOG_MAGIC || h->version != KLOG_VERSION) return 0; if (h->size != bytes - sizeof(struct klog_hdr)) return 0; if (h->sum != checksum(h)) return 0; // head and mark are outside the sum, so they are checked for sense instead: // a boot cannot have ended before it started, and nothing this kernel does // writes a quarter of a petabyte to a log. if (h->mark > h->head) return 0; if (h->head > (1ULL << 48)) return 0; return 1; } static void raw_putc(char c) { klog->data[klog->head % klog->size] = c; klog->head++; } static void raw_puts(const char *s) { while (*s) raw_putc(*s++); } // "[ 2.84] ", from the timer tick. Written by hand because the only // formatter in the kernel is cprintf, and cprintf is what calls this. static void stamp(void) { uint t = ticks; uint sec = t / 100; uint cs = t % 100; char b[16]; int i = 0, j; raw_putc('['); if (sec == 0) { b[i++] = '0'; } else { while (sec && i < 12) { b[i++] = '0' + (sec % 10); sec /= 10; } } for (j = i; j < 6; j++) raw_putc(' '); while (i-- > 0) raw_putc(b[i]); raw_putc('.'); raw_putc('0' + (cs / 10)); raw_putc('0' + (cs % 10)); raw_putc(']'); raw_putc(' '); } void klog_putc(int c) { char ch = (char)c; // Carriage returns and the console's backspace are cursor movement, not // content. A log full of them reads as corruption. if (ch == '\r' || c == BACKSPACE || ch == 0) return; if (!klog) { if (nearly < (int)sizeof(early)) early[nearly++] = ch; else early_lost = 1; return; } if (at_line_start && ch != '\n') stamp(); raw_putc(ch); at_line_start = (ch == '\n'); } // The log's own region. // // It is not on any allocator's list and never will be -- kinit1 is started // above it -- so the only way to discover that something has been handed a // page of it is to ask here. A page of the log turning up on kalloc's free // list is the failure mode this whole region is arranged to avoid, and this // is what would say so. static void klog_whose(struct sbuf *out, struct whose *w) { addr_t base, kva; if (!klog) return; base = (addr_t)klog; kva = (addr_t)P2V(w->phys); if (kva < base || kva >= base + KLOG_BYTES) return; w->owners++; sb_puts(out, " klog the kernel log, "); sb_putu(out, (kva - base) / 1024); sb_puts(out, " KB into a "); sb_putu(out, KLOG_BYTES / 1024); sb_puts(out, " KB region\n"); } void klog_init(void *base, uint64 bytes) { struct klog_hdr *h = (struct klog_hdr *)base; if (bytes <= sizeof(struct klog_hdr)) return; if (looks_valid(h, bytes)) { recovered = 1; prev_bytes = h->head - h->mark; // what the *last* boot wrote } else { // Either the first boot on this machine or a region something else has // been using. Either way the contents cannot be trusted, and printing // somebody else's bytes as if they were a log would be worse than // printing nothing. h->magic = KLOG_MAGIC; h->version = KLOG_VERSION; h->size = (uint32)(bytes - sizeof(struct klog_hdr)); h->boot = 0; h->head = 0; recovered = 0; prev_bytes = 0; } h->mark = h->head; h->boot++; h->sum = checksum(h); klog = h; // A divider in the log itself rather than a flag a reader has to know about: // whoever ends up reading this will be reading text, possibly by eye, and a // line that says where one boot ends is worth more than a field that has to // be interpreted. at_line_start = 1; raw_puts("\n--- boot "); { char b[12]; int i = 0; uint32 n = h->boot; if (n == 0) b[i++] = '0'; while (n) { b[i++] = '0' + (n % 10); n /= 10; } while (i-- > 0) raw_putc(b[i]); } raw_puts(" ---\n"); for (int i = 0; i < nearly; i++) { char ch = early[i]; if (ch == '\r' || ch == 0) continue; if (at_line_start && ch != '\n') stamp(); raw_putc(ch); at_line_start = (ch == '\n'); } if (early_lost) raw_puts("klog: early output overflowed and some was dropped\n"); nearly = 0; h->sum = checksum(h); dbg_register_whose("klog", klog_whose); // Said out loud on every boot, because "the log survived" and "the log was // silently started over" look identical in a file that begins with a boot // divider either way. if (recovered) kinfo("klog: %d KB at %p, %d bytes carried over from the previous boot\n", (int)(bytes / 1024), (uint64)base, (int)prev_bytes); else kinfo("klog: %d KB at %p, nothing recoverable was there\n", (int)(bytes / 1024), (uint64)base); } // How many bytes the ring currently holds, oldest first. uint64 klog_len(void) { if (!klog) return 0; return klog->head < klog->size ? klog->head : klog->size; } uint64 klog_prev_bytes(void) { return prev_bytes; } int klog_recovered(void) { return recovered; } // Read at a byte offset into the log, where 0 is the oldest byte still held. // // Serving straight out of the ring rather than rendering into a scratch buffer // the way every other /proc file does, because this file is 128 KB and that // pattern regenerates the whole thing on every read into a stack array. See // procread() in kernel/dev/procfs.c. int klog_read(uint64 off, char *dst, int n) { uint64 have, first; int i; if (!klog || n <= 0) return 0; have = klog_len(); if (off >= have) return 0; // EOF if ((uint64)n > have - off) n = (int)(have - off); first = klog->head - have; // logical position of the oldest byte for (i = 0; i < n; i++) dst[i] = klog->data[(first + off + i) % klog->size]; return n; }