SchOS/kernel/core/klog.c

// 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"

// 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');
}

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);

  // 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)
    cprintf("klog: %d KB at %p, %d bytes carried over from the previous boot\n",
            (int)(bytes / 1024), (uint64)base, (int)prev_bytes);
  else
    cprintf("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;
}