admin/LithosAnanake
1
1
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat(log): LOG-FLUSH -- a VM's log records reach Artemis's log ring; and the ring keeps its order when it grows

Browse Source 
FABRIC-3 SXXXII.4's deferred LOG-FLUSH, built to the 2026-10-14 rulings
(SXXXVIII): everything a VM logs, at or above the log level, goes into its
own buffer; it goes to Artemis on LOG-FLUSH, when full, and at once on an
ERROR, as one kernel-Hermes LOG_BATCH message she writes on her own turn,
the source being the sender the kernel stamped.  Records that cannot go yet
are counted and reported with the next flush.  LOG-SHOW (Hera only) reads
the ring back -- it had no reader.

Found by the first test that filled it: ring growth overwrote the oldest
record and put blank slots inside the live range.  Fixed test first.

Three ISAs: POST 1052 passed; new parity baseline word_count=526
hash=0x82f4ae7cb2e2d424 (deliberate).  CLAUDE.md: Phase 8 PKI closed.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
rajames
2026-10-14 12:10:01 -04:00
co-authored by Claude Opus 5.5
parent 5e26fad30d
commit 4da370f492
35 changed files with 91102 additions and 15 deletions
Download Patch File Download Diff File Expand all files Collapse all files
kernel/Makefile
+2 -1
View File
@@ -592,7 +592,8 @@ LOADER_EXTRA_SRCS := \
$(KERNEL_SRC)/vm/stadium_words.c \
$(KERNEL_SRC)/vm/stadium_blocks.c \
$(KERNEL_SRC)/vm/session.c \
$(KERNEL_SRC)/vm/kernel_hermes.c
$(KERNEL_SRC)/vm/kernel_hermes.c \
$(KERNEL_SRC)/vm/vm_log_buffer.c
KERNEL_EXTRA_SRCS := $(LOADER_EXTRA_SRCS)
kernel/include/starkernel/log_region.h
+10
View File
@@ -182,6 +182,16 @@ int log_region_append(uint8_t level, uint64_t timestamp,
const char *source, uint32_t source_len,
const char *msg, uint32_t msg_len);
/**
* log_region_read_recent - read one record back (2026-10-14, for LOG-SHOW).
*
* @param back 0 for the newest record, 1 for the one before it, ...
* @param out Filled with the record.
* @return 0 on success, 1 if there is no such record (the ring holds fewer
* than back+1, or none at all), -1 on a read failure or no ring.
*/
int log_region_read_recent(uint32_t back, log_slot_t *out);
#ifdef __cplusplus
}
#endif
kernel/include/starkernel/vm/kernel_hermes.h
+6
View File
@@ -728,6 +728,12 @@ int sk_hermes_reassemble(SkHermesMessage **chunks, int n_chunks,
* new one invented alongside it. */
#define SK_HERMES_MSG_TYPE_BLK_ATTACH 9
/* SK_HERMES_MSG_TYPE_LOG_BATCH (2026-10-14, FABRIC-3.md SXXXVIII): a VM's
* log records, binary (vm_log_buffer.h), for Artemis's log ring. The one
* type that is not FORTH text: sk_hermes_drain_checkpoint() hands it to
* vm_log_batch_deliver() instead of interpreting it. */
#define SK_HERMES_MSG_TYPE_LOG_BATCH 10
/* SK_HERMES_MSG_TYPE_CONSOLE_CMD (FABRIC-3.6.md task 3.9, Stage D) --
* same reasoning as SK_HERMES_MSG_TYPE_BLK_ATTACH above: deliberately
* reuses messaging.4th's own CONSOLE-CMD-EVENT value (7), since this is
kernel/include/starkernel/vm_log_buffer.h
+63
View File
@@ -0,0 +1,63 @@
/*
StarForth — Steady-State Virtual Machine Runtime
Copyright (c) 2023–2026 Robert A. James
All rights reserved.
This file is part of the StarForth project.
Licensed under the StarForth License, Version 1.0 (the "License");
you may not use this file except in compliance with the License.
*/
/**
* vm_log_buffer.h - a VM's log records, on their way to Artemis's log ring
* (FABRIC-3.md §XXXVIII, 2026-10-14; Captain Bob's rulings that day).
*
* Every record log_message() makes while a VM is the one attributed
* (vm_log_attributed_vm()) is packed into that VM's own buffer (VM.log_buf).
* The buffer goes to Artemis as one kernel-Hermes message (type
* SK_HERMES_MSG_TYPE_LOG_BATCH) on LOG-FLUSH, when the next record would not
* fit, and at once after an ERROR record. Artemis takes it on her own turn
* (the one delivery path, §XXXVI) and writes each record to her log ring
* (log_region.c), its source the VM the kernel stamped as sender -- never a
* name the sender supplies. Records that cannot be sent yet (Artemis not
* live, the send refused) are counted, never silently lost: the next flush
* that can be sent carries "N log records not sent" first.
*
* Record layout in a buffer and a batch: level (1 byte), timestamp (8,
* shim.c's KRELTSC base), length (2), then the text.
*/
#ifndef STARKERNEL_VM_LOG_BUFFER_H
#define STARKERNEL_VM_LOG_BUFFER_H
#ifdef __STARKERNEL__
#include <stdint.h>
#include "starkernel/vm_uuid.h"
struct VM;
/* Adds one record to vm's buffer (flushing first if it would not fit, and
* after it if it is an ERROR). Never logs; a call made while the buffer is
* already being worked on (a log line from inside a flush) is dropped and
* counted. */
void vm_log_buffer_add(struct VM *vm, uint8_t level, uint64_t timestamp,
const char *msg, uint32_t len);
/* Sends vm's buffer to Artemis. Returns the number of records sent, 0 when
* there was nothing to send, -1 when it could not be sent (the records are
* then counted in vm->log_lost). */
int vm_log_buffer_flush(struct VM *vm);
/* Artemis's side, called by sk_hermes_drain_checkpoint() for a
* SK_HERMES_MSG_TYPE_LOG_BATCH message, in her own context: writes each
* record to the log ring, its source the sender `from`. Returns the
* number written; -1 if vm is not Artemis (the batch is then dropped). */
int vm_log_batch_deliver(struct VM *vm, VMUuid from,
const uint8_t *payload, uint32_t payload_len);
#endif /* __STARKERNEL__ */
#endif /* STARKERNEL_VM_LOG_BUFFER_H */
kernel/src/capsule/mama_forth_words.c
+46
View File
@@ -49,6 +49,7 @@
#include "starkernel/capsule_mint.h"
#include "starkernel/user_identity_seed.h"
#include "starkernel/vm_identity.h"
#include "starkernel/log_region.h" /* LOG-SHOW */
#include "starkernel/capsule_loader.h"
#include "starkernel/capsule_run.h"
#include "starkernel/capsule_loader.h"
@@ -1379,6 +1380,49 @@ static void mama_word_name_to_xt(VM *vm)
vm_push(vm, (cell_t)(uintptr_t)e);
}
/**
* @brief LOG-SHOW ( n -- )
* Prints the newest n records of Artemis's log ring, oldest of them first:
* source, level, text (2026-10-14, FABRIC-3.md SXXXVIII). Hera's only --
* it shows every VM's records, and Hera's console is Zuse's.
*/
static void mama_word_log_show(VM *vm)
{
static const char *names[] = { "ERROR", "WARN ", "INFO ", "TEST ", "DEBUG" };
static log_slot_t slot; /* 1 KiB: static, not on the stack */
static char text[LOG_SLOT_MSG_MAX + 1];
cell_t n;
int32_t back;
if (vm->dsp < 0) {
console_println("LOG-SHOW: expects a count -- nothing on the stack");
vm->error = 1;
return;
}
n = vm_pop(vm);
if (n > 128) n = 128;
for (back = (int32_t)n - 1; back >= 0; back--) {
int rc = log_region_read_recent((uint32_t)back, &slot);
uint32_t len;
char src[LOG_SLOT_SOURCE_MAX + 1];
if (rc < 0) {
console_println("LOG-SHOW: no log ring -- Artemis's disk not attached");
return;
}
if (rc > 0) continue; /* fewer records than asked for */
len = slot.msg_len < LOG_SLOT_MSG_MAX ? slot.msg_len : LOG_SLOT_MSG_MAX;
memcpy(text, slot.msg, len);
text[len] = '\0';
memcpy(src, slot.source, LOG_SLOT_SOURCE_MAX);
src[LOG_SLOT_SOURCE_MAX] = '\0';
console_puts(src);
console_puts(" ");
console_puts(names[slot.level <= 4 ? slot.level : 0]);
console_puts(" ");
console_println(text);
}
}
/**
* @brief RUNCAP-TEST ( caddr u -- ok? rc )
* Diagnostic-only word (FABRIC-2.md §F.6/§F.18): calls
@@ -2275,6 +2319,7 @@ void register_mama_forth_words(VM *vm)
register_word(vm, "WORKER-BIRTH", mama_word_worker_birth);
register_word(vm, "UNATTENDED-BIRTH", mama_word_unattended_birth);
register_word(vm, "CONSOLE-ATTACH", mama_word_console_attach);
register_word(vm, "LOG-SHOW", mama_word_log_show);
register_word(vm, "NAME>XT", mama_word_name_to_xt);
register_word(vm, "RUNCAP-TEST", mama_word_runcap_test);
register_word(vm, "PAIR-TEST", mama_word_pair_test);
@@ -2337,6 +2382,7 @@ void register_mama_forth_words(VM *vm)
register_word(vm, "WORKER-BIRTH", mama_word_worker_birth);
register_word(vm, "UNATTENDED-BIRTH", mama_word_unattended_birth);
register_word(vm, "CONSOLE-ATTACH", mama_word_console_attach);
register_word(vm, "LOG-SHOW", mama_word_log_show);
register_word(vm, "NAME>XT", mama_word_name_to_xt);
register_word(vm, "RUNCAP-TEST", mama_word_runcap_test);
register_word(vm, "PAIR-TEST", mama_word_pair_test);
kernel/src/log_region.c
+35 -5
View File
@@ -116,14 +116,32 @@ int log_region_append(uint8_t level, uint64_t timestamp,
uint32_t total_slots = ctrl.devblocks * LOG_SLOTS_PER_DEVBLOCK;
if (ctrl.record_count >= total_slots) {
if (ctrl.devblocks < LOG_REGION_MAX_DEVBLOCKS) {
/* Grow: new slots appear at indices [old_total_slots ..
* new_total_slots-1], nothing already written moves -- safe
* to do at any point in the ring's lifecycle regardless of
* wrap state, since head/tail are slot INDICES modulo
* total_slots, and the modulus is simply larger from here on. */
/* Grow: new slots appear at indices [old_total .. new_total-1].
* The ring is full here, so head == tail, and in ring order the
* records run head..old_total-1 then 0..head-1. The new slots
* must come after the newest record and before the oldest, so
* the records from head on move up by the slots added, and the
* next write goes into the gap they leave (or, with head at 0,
* simply at old_total). Until 2026-10-14 nothing moved and
* tail stayed put: the next write overwrote the oldest record,
* and the blank new slots read back as records inside the live
* range (FABRIC-3.md SXXXVIII -- first exercised by LOG-FLUSH). */
uint32_t old_total = total_slots, added, i;
ctrl.devblocks += LOG_REGION_GROWTH_INCREMENT;
if (ctrl.devblocks > LOG_REGION_MAX_DEVBLOCKS) ctrl.devblocks = LOG_REGION_MAX_DEVBLOCKS;
total_slots = ctrl.devblocks * LOG_SLOTS_PER_DEVBLOCK;
added = total_slots - old_total;
if (ctrl.head_slot == 0) {
ctrl.tail_slot = old_total;
} else {
for (i = old_total; i-- > ctrl.head_slot; ) {
log_slot_t moving;
if (log_region_read_slot(i, &moving) != 0) return -1;
if (log_region_write_slot(i + added, &moving) != 0) return -1;
}
ctrl.tail_slot = ctrl.head_slot;
ctrl.head_slot += added;
}
}
if (ctrl.record_count >= total_slots) {
/* Still full (growth ceiling already reached) -- evict oldest,
@@ -175,3 +193,15 @@ int log_region_append(uint8_t level, uint64_t timestamp,
return log_region_ctrl_write(&ctrl);
}
int log_region_read_recent(uint32_t back, log_slot_t *out) {
log_region_ctrl_t ctrl;
uint32_t total_slots;
if (!out) return -1;
if (log_region_ctrl_read(&ctrl) != 0) return -1;
if (back >= ctrl.record_count) return 1;
total_slots = ctrl.devblocks * LOG_SLOTS_PER_DEVBLOCK;
if (total_slots == 0) return 1;
return log_region_read_slot((ctrl.tail_slot + total_slots - 1u - back) % total_slots, out);
}
kernel/src/vm/host/shim.c
+10
View File
@@ -63,6 +63,8 @@
* message line length (renamed LOG_MSG_LINE_MAX, 256) no longer share a
* name, so include order is irrelevant here. */
#include "starkernel/repl.h"
#include "starkernel/log_attrib.h" /* vm_log_attributed_vm() */
#include "starkernel/vm_log_buffer.h" /* vm_log_buffer_add() */
#include "starkernel/vm/bootstrap/sk_vm_bootstrap.h"
#include "log.h"
#include "vm_host.h"
@@ -335,6 +337,14 @@ void log_message(LogLevel level, const char *fmt, ...) {
console_puts(reset);
console_puts(prefix);
console_println(buf);
/* And into the log buffer of the VM it belongs to, for Artemis's log
* ring (2026-10-14, FABRIC-3.md SXXXVIII). A record made outside any
* VM's text -- the kernel's own -- belongs to none and is not kept. */
{
struct VM *owner = vm_log_attributed_vm();
if (owner) vm_log_buffer_add(owner, (uint8_t)idx, rel_tsc, buf, (uint32_t)strlen(buf));
}
}
/**
kernel/src/vm/kernel_hermes.c
+11
View File
@@ -55,6 +55,7 @@
#include "starkernel/vm/switch.h" /* one path: sk_vm_switch_current_vm() */
#include "starkernel/log_attrib.h" /* one path: vm_log_attributed_vm() */
#include "starkernel/capsule_vm_switch_signal.h" /* one path: sk_vm_switch_signal_mark_work() */
#include "starkernel/vm_log_buffer.h" /* vm_log_batch_deliver() */
/* Freestanding: no libc printf. Prints an unsigned decimal, no leading
* zeros -- same small helper stadium.c/capsule_vm_switch_signal.c each
@@ -656,6 +657,16 @@ int sk_hermes_drain_checkpoint(VM *vm) {
console_println(line);
}
/* A log batch is records, not FORTH text: written to Artemis's log ring
* here, in her own context (2026-10-14, FABRIC-3.md SXXXVIII). */
if (msg->type == SK_HERMES_MSG_TYPE_LOG_BATCH) {
sk_hermes_pending_pop(self);
(void)vm_log_batch_deliver(vm, msg->from, (const uint8_t *)msg->payload_addr,
msg->payload_len);
sk_hermes_release(msg);
return 1;
}
/* Off the queue BEFORE it runs (2026-10-14): running it can reach a
* colon-word checkpoint that drains this same VM again, and that
* drain must find the next message, not this one -- popped only after,
kernel/src/vm/vm_log_buffer.c
+143
View File
@@ -0,0 +1,143 @@
/*
StarForth — Steady-State Virtual Machine Runtime
Copyright (c) 2023–2026 Robert A. James
All rights reserved.
This file is part of the StarForth project.
Licensed under the StarForth License, Version 1.0 (the "License");
you may not use this file except in compliance with the License.
*/
/**
* vm_log_buffer.c - a VM's log records, on their way to Artemis's log ring.
* See the header for the contract (FABRIC-3.md §XXXVIII, 2026-10-14).
*/
#ifdef __STARKERNEL__
#include "starkernel/vm_log_buffer.h"
#include "vm.h"
#include "log.h" /* LOG_ERROR, LOG_WARN */
#include "starkernel/vm/kernel_hermes.h" /* sk_hermes_send_one(), SK_HERMES_MSG_TYPE_LOG_BATCH */
#include "starkernel/capsule_birth.h" /* capsule_vm_find_by_name_nocase(), capsule_vm_registry_get() */
#include "starkernel/log_region.h" /* log_region_append() */
#include "starkernel/console.h" /* console_println() -- never log_message() here */
#include "freestanding/stdio.h" /* snprintf() */
#include <string.h>
#define REC_HEAD 11u /* level 1 + timestamp 8 + length 2 */
typedef char vm_log_buf_fits[(VM_LOG_BUF_SIZE + 64 <= SK_HERMES_CHUNK_MAX_PAYLOAD) ? 1 : -1];
/* Set while a record is being added or a buffer sent: a log line made from
* inside that work (a kernel-Hermes refusal, say) must not re-enter it. */
static int g_busy;
static uint32_t put_record(uint8_t *at, uint8_t level, uint64_t ts,
const char *msg, uint16_t len) {
at[0] = level;
memcpy(at + 1, &ts, 8);
memcpy(at + 9, &len, 2);
memcpy(at + REC_HEAD, msg, len);
return REC_HEAD + len;
}
static uint32_t count_records(const uint8_t *buf, uint32_t len) {
uint32_t at = 0, n = 0;
while (at + REC_HEAD <= len) {
uint16_t l;
memcpy(&l, buf + at + 9, 2);
at += REC_HEAD + l;
n++;
}
return n;
}
static int send_buffer(VM *vm) {
uint8_t payload[SK_HERMES_CHUNK_MAX_PAYLOAD];
uint32_t len = 0, records = count_records(vm->log_buf, vm->log_buf_len);
VMRegistryEntry artemis;
if (vm->log_buf_len == 0 && vm->log_lost == 0) return 0;
if (vm->log_lost > 0) {
char note[64];
int n = snprintf(note, sizeof(note), "%u log records not sent: Artemis not ready",
(unsigned)vm->log_lost);
if (n > 0) len += put_record(payload, LOG_WARN, 0, note, (uint16_t)n);
}
memcpy(payload + len, vm->log_buf, vm->log_buf_len);
len += vm->log_buf_len;
if (capsule_vm_find_by_name_nocase("Artemis", &artemis) != 0 || !artemis.vm_ptr ||
(artemis.state != VM_STATE_LIVE && artemis.state != VM_STATE_SWITCHED_OUT) ||
sk_hermes_send_one(vm->stadium_vm_id, artemis.vm_id, SK_HERMES_MSG_TYPE_LOG_BATCH,
0, payload, len) != 0) {
vm->log_lost += records;
vm->log_buf_len = 0;
return -1;
}
vm->log_lost = 0;
vm->log_buf_len = 0;
return (int)records;
}
void vm_log_buffer_add(VM *vm, uint8_t level, uint64_t timestamp,
const char *msg, uint32_t len) {
if (!vm || !msg) return;
if (g_busy) { vm->log_lost++; return; }
g_busy = 1;
if (len > VM_LOG_BUF_SIZE - REC_HEAD) len = VM_LOG_BUF_SIZE - REC_HEAD;
if (vm->log_buf_len + REC_HEAD + len > VM_LOG_BUF_SIZE) (void)send_buffer(vm);
vm->log_buf_len = (uint16_t)(vm->log_buf_len +
put_record(vm->log_buf + vm->log_buf_len, level, timestamp, msg, (uint16_t)len));
if (level == LOG_ERROR) (void)send_buffer(vm);
g_busy = 0;
}
int vm_log_buffer_flush(VM *vm) {
int rc;
if (!vm || g_busy) return -1;
g_busy = 1;
rc = send_buffer(vm);
g_busy = 0;
return rc;
}
int vm_log_batch_deliver(VM *vm, VMUuid from, const uint8_t *payload, uint32_t payload_len) {
VMRegistryEntry artemis, sender;
const char *source = "?";
uint32_t at = 0;
int written = 0, failed = 0;
if (capsule_vm_find_by_name_nocase("Artemis", &artemis) != 0 || artemis.vm_ptr != (void *)vm) {
return -1;
}
/* The source is the sender the kernel stamped on the message: a VM
* cannot write a record under another's name. */
if (capsule_vm_registry_get(from, &sender) == 0) source = sender.name;
while (at + REC_HEAD <= payload_len) {
uint8_t level = payload[at];
uint64_t ts;
uint16_t len;
memcpy(&ts, payload + at + 1, 8);
memcpy(&len, payload + at + 9, 2);
if (at + REC_HEAD + len > payload_len) break; /* malformed tail: stop */
if (log_region_append(level, ts, source, (uint32_t)strlen(source),
(const char *)payload + at + REC_HEAD, len) < 0) {
failed++;
} else {
written++;
}
at += REC_HEAD + len;
}
if (failed) console_println("Artemis: log ring write failed -- records not kept");
return written;
}
#endif /* __STARKERNEL__ */