SchOS/kernel/core/klog.c

// SPDX-License-Identifier: GPL-2.0-or-later
//
// The kernel log that outlives the kernel. See include/core/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 "core/types.h"
#include "core/defs.h"
#include "arch/memlayout.h"
#include "core/klog.h"
#include "core/sbuf.h"
#include "core/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; }

// How much of what the ring holds this boot wrote: the tail of it, since the
// ring is read oldest first. GMMOS shows this boot's log, not the last one's.
uint64
klog_boot_bytes(void)
{
  if (!klog)
    return 0;
  uint64 n = klog->head - klog->mark;
  return n < klog_len() ? n : klog_len();
}
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;
}

// Render the ring as syslog(2) records, for dmesg.
//
// The ring holds plain readable text -- `[     0.00] e820: ...` -- because it
// is also what a person reads with `cat /proc/kmsg`, and what PSOGM points at
// after a crash. syslog(2)'s callers expect Linux's record format, which is
// the same line with a priority in front:
//
//     <6>[     0.00] e820: 1017 MB usable in 8 regions
//
// toybox's dmesg parses each line with
//
//     sscanf(msg, "<%u>[%llu.%llu] %n", ...) != 3 -> return
//
// and *silently drops* anything that does not match. So a working syslog(2)
// handing back the ring verbatim produced an empty dmesg with no error: every
// line was parsed, rejected and discarded. Only the `<6>` was missing -- the
// bracketed timestamp already matches, because scanf skips the leading spaces.
//
// Rendering here rather than storing the prefix in the ring: the write path
// runs in panic context and from every cprintf, and the stored form is read by
// humans. An ABI detail belongs at the boundary that has the ABI, which is the
// same rule sigset_from_user() follows one directory over.
//
// <6> is KERN_INFO. There are no per-message levels to derive one from, and
// inventing severity from the text would be a worse lie than a constant.
int
klog_render_syslog(char *dst, int cap)
{
  uint64 have = klog_len(), off = 0;
  int out = 0, atline = 1;
  char chunk[128];

  if (!klog || cap <= 0 || have == 0)
    return 0;

  // Linux returns the *most recent* `cap` bytes. The prefix makes the output
  // longer than the source, so find the first whole line that lets the rest
  // fit: count what a render from `off` would cost, and drop lines from the
  // front until it does. Whole lines, because half a record is worse to a
  // parser than a missing one.
  for (;;) {
    uint64 scan = off;
    int need = 0, nl = 1;         // nl: next byte starts a line
    while (scan < have) {
      int got = klog_read(scan, chunk, sizeof(chunk));
      if (got <= 0)
        break;
      for (int i = 0; i < got; i++) {
        if (nl) { need += 3; nl = 0; }
        need++;
        if (chunk[i] == '\n') nl = 1;
      }
      scan += got;
    }
    if (need <= cap || off >= have)
      break;
    // Advance past one line.
    uint64 p = off;
    int done = 0;
    while (p < have && !done) {
      int got = klog_read(p, chunk, sizeof(chunk));
      if (got <= 0) { off = have; break; }
      for (int i = 0; i < got; i++) {
        p++;
        if (chunk[i] == '\n') { off = p; done = 1; break; }
      }
      if (!done) off = p;
    }
    if (!done && off >= have)
      break;
  }

  while (off < have && out < cap) {
    int got = klog_read(off, chunk, sizeof(chunk));
    if (got <= 0)
      break;
    for (int i = 0; i < got && out < cap; i++) {
      if (atline) {
        if (out + 3 > cap)
          return out;             // never emit half a prefix
        dst[out++] = '<'; dst[out++] = '6'; dst[out++] = '>';
        atline = 0;
      }
      dst[out++] = chunk[i];
      if (chunk[i] == '\n')
        atline = 1;
    }
    off += got;
  }
  return out;
}