store: the kernel captures its own events, as classed records

Every part of this was in place except the point of it: a record can carry a 16-bit class,
CUBE_OP_PUT stamps one and CUBE_OP_FLAG_SCAN retrieves by class, the vocabulary is a userspace
convention, and the kernel already stamped its own boot record with the boot class. What was
missing was a kernel that captures *events* — one that writes about what happened to it rather
than only what a caller asked for. Until now the kernel's account of saying no was a line in
dmesg, which is not somewhere a later reader can ask.

Three events, in the events space (0xFB), each classed by the vocabulary it belongs to:

  bad-op         ERROR   a request the interface does not offer, refused and recorded
  clock-set      BOOT    the epoch was provisional, and the record was rewritten
  boot-record-late ERROR|BOOT  the record only landed on a retry — the one that matters most,
                         because that defect's effect was invisible in the store

The write is bounded twice (EVENT_BUDGET, 32 a boot; REFUSAL_BUDGET, 8 among them) and that is
not tidiness: a kernel that appends a record per event can turn a storm of refused requests into
a storm of writes, which this store has already met from the other side when a walk with no store
behind it served ~200,000 invented records a minute. Past the ceiling the kernel logs and stops.

The refusal capture is exported for the syscall layer to call (`cubelinux_kernel_capture_refusal`)
because that is where the refusals that leave the store usable happen — a bad size, an op that
does not exist, a value past the maximum. A store that cannot be read at all is the one refusal
the kernel cannot record into itself, and that is stated rather than papered over.

drivers/cube/cube_syscall.c

@@ -34,6 +34,13 @@ int cubelinux_kernel_put(const __u8 *space, __u64 x, __u64 y, __u64 z,
 ssize_t cubelinux_kernel_get(const __u8 *space, __u64 x, __u64 y, __u64 z,
 			     void *buf, size_t len, __u16 *out_flags);
 int cubelinux_kernel_del(const __u8 *space, __u64 x, __u64 y, __u64 z);
+/*
+ * Capture a request this layer refused, as a classed record in the events space. The refusals worth
+ * recording are the ones that leave the store usable — a caller asking for something the interface
+ * does not offer — because those are the moments the machine said no and carried on. It takes the
+ * driver's write lock itself, so it must be called from here and not from inside an op.
+ */
+int cubelinux_kernel_capture_refusal(__u64 op, int errno, const __u8 *kind, size_t kind_len);
 int cubelinux_kernel_sync(void);
 
 /*
@@ -156,8 +163,10 @@ static long cube_args_op(unsigned int op, void __user *uargs)
 	 * The size is the caller's, and it must be the one this kernel implements: a caller
 	 * built against a later block would otherwise have fields silently ignored.
 	 */
-	if (args.size != sizeof(struct cube_args))
+	if (args.size != sizeof(struct cube_args)) {
+		cubelinux_kernel_capture_refusal(op, EINVAL, "bad-size", 8);
 		return -EINVAL;
+	}
 
 	switch (op) {
 	case CUBE_OP_PUT:
@@ -167,12 +176,15 @@ static long cube_args_op(unsigned int op, void __user *uargs)
 	case CUBE_OP_SYNC:
 		break;
 	default:
+		cubelinux_kernel_capture_refusal(op, EINVAL, "bad-op", 6);
 		return -EINVAL;
 	}
 
 	if (op == CUBE_OP_PUT || op == CUBE_OP_GET) {
-		if (args.len > CUBE_MAX_VALUE)
+		if (args.len > CUBE_MAX_VALUE) {
+			cubelinux_kernel_capture_refusal(op, E2BIG, "too-big", 7);
 			return -E2BIG;
+		}
 		if (args.len > 0) {
 			buf = kvmalloc(args.len, GFP_KERNEL);
 			if (!buf)

drivers/cube/cubelinux_store.rs

@@ -41,7 +41,7 @@
 //! ```
 
 use core::fmt::{self, Write};
-use core::sync::atomic::{AtomicBool, AtomicI64, AtomicU32, Ordering};
+use core::sync::atomic::{AtomicBool, AtomicI64, AtomicU32, AtomicU64, Ordering};
 
 // The store's format, in one file, shared with userspace.
 //
@@ -336,6 +336,46 @@ const BOOT_RECORD_MAX_REFRESHES: u32 = 2;
 /// Both are whole seconds read one after the other, so a second of slack belongs here.
 const CLOCK_SET_TOLERANCE_SECS: i64 = 2;
 
+/// The space the **kernel captures its own events into**: `0xFB` repeated, reserved for events.
+///
+/// The same shape and the same reason as [`BOOT_SPACE`]: the driver cannot link `cube-core`, so the
+/// tag is written out on both sides and `verify-event-capture` is what holds them together — the
+/// guest scans this space at the raw `0xFB` and userspace scans it by the name `events`, and the
+/// bytes have to come back the same.
+const EVENT_SPACE: [u8; SPACE_ID_LEN] = [0xFB; SPACE_ID_LEN];
+
+/// The class bits the kernel stamps on the events it captures, spelled out from the events
+/// vocabulary in `cube-core::wordflags::EventFlags` and checked against it by the same gate.
+///
+/// `ERROR` (1<<5) is the vocabulary's mark that an event went wrong — it *combines*, which is why a
+/// refused request is `ERROR` and a request refused while writing the record about a boot is
+/// `ERROR | BOOT`.
+const EVENT_ERROR: u16 = 1 << 5;
+/// The class the kernel's own boot record already carries. The vocabulary's boot class.
+const EVENT_BOOT: u16 = 1 << 7;
+
+/// The coordinate the next captured event goes to: a sequence, so events accumulate.
+///
+/// This is the one place the kernel's own writing differs from its boot record, and deliberately:
+/// the boot record is *one* record at `(0,0,0)` saying "this boot", overwritten each boot, because
+/// that is what "which boot is this" needs. Events are a series, so they get distinct coordinates
+/// and are not overwritten — which is also why they need a ceiling (below).
+static EVENT_SEQ: AtomicU64 = AtomicU64::new(0);
+
+/// How many events this kernel may write by itself in one boot, and how many refusals among them.
+///
+/// The bound is not tidiness. A kernel that appends a record per event is a kernel that can turn a
+/// storm of refused requests into a storm of *writes*, and this store has already been through that
+/// from the other side: a walk with no store behind it served about two hundred thousand invented
+/// records a minute, which became two hundred thousand writes once the walk was made to answer. The
+/// ceiling means the kernel's own account of itself can never be the thing that fills the store —
+/// past it the kernel logs and stops, and says so in the log rather than quietly shaping the record.
+const EVENT_BUDGET: u32 = 32;
+static EVENTS_WRITTEN: AtomicU32 = AtomicU32::new(0);
+/// Refusals have their own, smaller ceiling: they are the class a caller or a bug can drive.
+const REFUSAL_BUDGET: u32 = 8;
+static REFUSALS_WRITTEN: AtomicU32 = AtomicU32::new(0);
+
 
 /// FNV-1a offset basis.
 const FNV_OFFSET: u64 = cube_format::FNV_OFFSET;
@@ -2073,11 +2113,118 @@ fn refresh_boot_record_if_the_clock_was_set() {
             BOOT_RECORD_WALL.store(wall, Ordering::Release);
             BOOT_RECORD_MONO.store(mono, Ordering::Release);
             pr_info!("cubelinux: the clock was set, so this boot's record was rewritten with the corrected time\n");
+            // And the event goes in the store, not only in the log: the record about the boot now
+            // carries a time that was provisional for a while, and this is the record that says so.
+            if !capture_event(
+                EVENT_BOOT,
+                b"clock-set",
+                b"the boot record's epoch was rewritten after a correction",
+            ) {
+                pr_warn!("cubelinux: could not capture the clock-set event (budget or store)\n");
+            }
         }
         Err(_) => pr_warn!("cubelinux: could not rewrite this boot's record after a clock correction\n"),
     }
 }
 
+/// Capture one event into the events space, as a record like any other.
+///
+/// The value is `event=<kind> uptime=<seconds since boot>[ <detail>]`, and it is classed by the
+/// caller's mask. Nothing about it is privileged: it is a record in a space, written through the
+/// same bounded append every other write takes, readable back through `cube(2)` and findable with a
+/// class scan — which is the whole point. The kernel's account of what happened to it stops being
+/// something you have to have been watching `dmesg` to know.
+///
+/// **Called with `STORE_OP` held** (the write path holds it, and so does the C-facing wrapper
+/// below), and bounded twice — see [`EVENT_BUDGET`] and [`REFUSAL_BUDGET`]. Returns whether the
+/// event was actually written, because a caller that logs "captured" when the budget was spent
+/// would be lying in the log about the store.
+fn capture_event(flags: u16, kind: &[u8], detail: &[u8]) -> bool {
+    if EVENTS_WRITTEN.load(Ordering::Acquire) >= EVENT_BUDGET {
+        return false;
+    }
+    if flags & EVENT_ERROR != 0 && REFUSALS_WRITTEN.load(Ordering::Acquire) >= REFUSAL_BUDGET {
+        return false;
+    }
+    let seq = EVENT_SEQ.fetch_add(1, Ordering::AcqRel);
+    let (_, mono) = now_clocks();
+
+    let mut value = KVVec::<u8>::new();
+    if push(&mut value, b"event=").is_none()
+        || push(&mut value, kind).is_none()
+        || push(&mut value, b" uptime=").is_none()
+        || push_dec(&mut value, mono.max(0) as u64).is_none()
+    {
+        return false;
+    }
+    if !detail.is_empty()
+        && (push(&mut value, b" ").is_none() || push(&mut value, detail).is_none())
+    {
+        return false;
+    }
+
+    let mutation = Mutation {
+        space: EVENT_SPACE,
+        key: morton_encode(seq, 0, 0),
+        flags,
+        value,
+    };
+    match append_mutation(&mutation, 1) {
+        Ok(_) => {
+            EVENTS_WRITTEN.fetch_add(1, Ordering::AcqRel);
+            if flags & EVENT_ERROR != 0 {
+                REFUSALS_WRITTEN.fetch_add(1, Ordering::AcqRel);
+            }
+            true
+        }
+        Err(_) => false,
+    }
+}
+
+/// Capture a request the kernel refused, called from the syscall layer.
+///
+/// The refusals worth recording are the ones that leave the store *usable*: a caller asking for
+/// something the interface does not offer (a bad size, a mode that is not a mode, a space that is
+/// not there). Those are the moments where the machine said no and carried on, which is exactly the
+/// behaviour this store is built around — and until now nothing recorded that it happened. A store
+/// that cannot be read at all is the one refusal that cannot be recorded *into the store*, and this
+/// does not pretend otherwise: it returns 0 and the log keeps that story.
+///
+/// Takes `STORE_OP` itself, so it must be called from outside the driver's write path — the C
+/// layer's argument checks are all before the driver is entered, which is the only place it is
+/// called from.
+///
+/// # Safety
+/// `kind` must point to `kind_len` readable bytes when `kind_len` is non-zero.
+#[unsafe(no_mangle)]
+pub unsafe extern "C" fn cubelinux_kernel_capture_refusal(
+    op: u64,
+    errno: i32,
+    kind: *const u8,
+    kind_len: usize,
+) -> i32 {
+    let kind = if kind_len == 0 || kind.is_null() {
+        &b"refused"[..]
+    } else {
+        // SAFETY: the caller guarantees `kind_len` readable bytes at `kind`.
+        unsafe { core::slice::from_raw_parts(kind, kind_len) }
+    };
+    let mut detail = KVVec::<u8>::new();
+    if push(&mut detail, b"op=").is_none()
+        || push_dec(&mut detail, op).is_none()
+        || push(&mut detail, b" errno=").is_none()
+        || push_dec(&mut detail, errno.unsigned_abs() as u64).is_none()
+    {
+        return 0;
+    }
+    let _op = STORE_OP.lock();
+    if capture_event(EVENT_ERROR, kind, detail.as_slice()) {
+        1
+    } else {
+        0
+    }
+}
+
 /// The kernel's own account of the boot it is having, as one line:
 /// `boot=<seconds since the epoch> uptime=<seconds since boot> clock=<raw|set> device=<the store it
 /// resolved> kernel=<its version banner>`.
@@ -2191,6 +2338,19 @@ fn ensure_boot_record() {
             BOOT_RECORD_MONO.store(mono, Ordering::Release);
             BOOT_RECORD_ATTEMPTS.store(BOOT_RECORD_MAX_ATTEMPTS, Ordering::Release);
             pr_info!("cubelinux: recorded this boot in the store\n");
+            // A boot whose record took more than one attempt is a boot where the switch was on and
+            // the effect was off for a while — the defect this retry exists for. The record that
+            // lands is the same record either way, so without this event the difference between
+            // "recorded first time" and "recorded on the third try" would be invisible in the store.
+            if made > 0
+                && !capture_event(
+                    EVENT_ERROR | EVENT_BOOT,
+                    b"boot-record-late",
+                    b"the record took more than one attempt",
+                )
+            {
+                pr_warn!("cubelinux: could not capture the late-boot-record event (budget or store)\n");
+            }
         }
         Err(_) => pr_warn!("cubelinux: the store would not take this boot's record\n"),
     }