From 19cdf8dc9f90edb53653e358b64bfb3dbbda114a Mon Sep 17 00:00:00 2001
From: Kevin Nguyen <kevinnguyen.alms@gmail.com>
Date: Wed, 29 Jul 2026 22:32:18 +0700
Subject: [PATCH] CB-505 fix: audit lines were not valid JSON
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

The first cut spliced the timestamp on via a logback pattern:

    {"ts":"%d{...}",%replace(%msg){'^\{',''}%n

Logback's variable substitution chokes on the literal braces
("All tokens consumed but was expecting }"), so the encoder failed to
configure. Caught by running the real jar and noticing logback had dumped its
internal status — which it only does when something failed to parse. The build
was green throughout: nothing asserted the audit trail was machine-readable.

AuditLog now emits the complete object including its own ISO-8601 "ts", and the
appender pattern is a bare %msg. Adds AuditLogTest, which parses each emitted
line with Jackson (so a malformed record fails the build) and pins that hostile
ids cannot escape their field to forge a second record.

311 tests green; logback now configures with zero internal errors.
---
 .../java/dev/ltms/bridged/auth/AuditLog.java  |  13 ++-
 bridged/src/main/resources/logback.xml        |   8 +-
 .../dev/ltms/bridged/auth/AuditLogTest.java   | 100 ++++++++++++++++++
 3 files changed, 115 insertions(+), 6 deletions(-)
 create mode 100644 bridged/src/test/java/dev/ltms/bridged/auth/AuditLogTest.java

diff --git a/bridged/src/main/java/dev/ltms/bridged/auth/AuditLog.java b/bridged/src/main/java/dev/ltms/bridged/auth/AuditLog.java
index e564466..1554dbd 100644
--- a/bridged/src/main/java/dev/ltms/bridged/auth/AuditLog.java
+++ b/bridged/src/main/java/dev/ltms/bridged/auth/AuditLog.java
@@ -3,6 +3,10 @@ package dev.ltms.bridged.auth;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
+import java.time.Instant;
+import java.time.ZoneOffset;
+import java.time.format.DateTimeFormatter;
+
 /**
  * Append-only record of privileged actions (CB-505).
  *
@@ -18,6 +22,8 @@ import org.slf4j.LoggerFactory;
 public final class AuditLog {
 
     private static final Logger AUDIT = LoggerFactory.getLogger("audit");
+    private static final DateTimeFormatter TS =
+            DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSSXXX").withZone(ZoneOffset.UTC);
 
     private AuditLog() {
     }
@@ -40,8 +46,11 @@ public final class AuditLog {
     private static void write(Principal caller, Authz.Action action, String target,
                               String outcome, String reason) {
         Principal c = caller != null ? caller : Principal.anonymous();
-        StringBuilder sb = new StringBuilder(160);
-        sb.append("{\"role\":\"").append(c.role()).append('"')
+        StringBuilder sb = new StringBuilder(200);
+        // The timestamp is built here rather than by the appender pattern: a pattern that wrapped
+        // literal braces around the message collides with logback's own variable substitution.
+        sb.append("{\"ts\":\"").append(TS.format(Instant.now())).append('"')
+                .append(",\"role\":\"").append(c.role()).append('"')
                 .append(",\"actor\":\"").append(esc(c.describe())).append('"')
                 .append(",\"pid\":").append(c.pid())
                 .append(",\"action\":\"").append(action).append('"')
diff --git a/bridged/src/main/resources/logback.xml b/bridged/src/main/resources/logback.xml
index 1407ceb..afa8ab5 100644
--- a/bridged/src/main/resources/logback.xml
+++ b/bridged/src/main/resources/logback.xml
@@ -8,9 +8,9 @@
     <!--
       CB-505 audit trail. Its own file, deliberately not the app log: privileged actions
       (spawn/stop/send/reply/drain) must stay greppable and shippable without dragging DEBUG noise
-      along. The message is already a JSON object (AuditLog builds it), so the pattern contributes
-      only an ISO-8601 timestamp — one appender owns the clock, so the trail cannot disagree with
-      itself. Rolls daily, 30 days retained, 100MB cap.
+      along. AuditLog emits a complete JSON object including its own ISO-8601 "ts" field, so the
+      pattern is a bare %msg — a pattern that spliced literal braces around the message would
+      collide with logback's own variable substitution. Rolls daily, 30 days retained, 100MB cap.
 
       NOTE: records carry who/what/target/outcome only. Message CONTENT is never written here —
       this bridge carries source code and prompts, and an audit log that accumulated them would be
@@ -25,7 +25,7 @@
             <totalSizeCap>100MB</totalSizeCap>
         </rollingPolicy>
         <encoder>
-            <pattern>{"ts":"%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX}",%replace(%msg){'^\{',''}%n</pattern>
+            <pattern>%msg%n</pattern>
         </encoder>
     </appender>
 
diff --git a/bridged/src/test/java/dev/ltms/bridged/auth/AuditLogTest.java b/bridged/src/test/java/dev/ltms/bridged/auth/AuditLogTest.java
new file mode 100644
index 0000000..3e35109
--- /dev/null
+++ b/bridged/src/test/java/dev/ltms/bridged/auth/AuditLogTest.java
@@ -0,0 +1,100 @@
+package dev.ltms.bridged.auth;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
+import com.fasterxml.jackson.databind.JsonNode;
+import com.fasterxml.jackson.databind.ObjectMapper;
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.slf4j.LoggerFactory;
+
+import static org.junit.jupiter.api.Assertions.*;
+
+/**
+ * CB-505 — the audit record's shape.
+ *
+ * <p>These exist because the first cut of this feature emitted lines that were <em>not</em> valid
+ * JSON: the timestamp was spliced on by a logback pattern whose literal braces collided with
+ * logback's variable substitution. The appender failed to parse, and nothing in the build noticed.
+ * An audit trail that silently stops being machine-readable is worse than none.
+ */
+class AuditLogTest {
+
+    private final ObjectMapper mapper = new ObjectMapper();
+    private ListAppender<ILoggingEvent> appender;
+    private ch.qos.logback.classic.Logger auditLogger;
+
+    @BeforeEach
+    void attach() {
+        LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory();
+        auditLogger = ctx.getLogger("audit");
+        appender = new ListAppender<>();
+        appender.setContext(ctx);
+        appender.start();
+        auditLogger.addAppender(appender);
+        auditLogger.setLevel(Level.INFO);
+    }
+
+    @AfterEach
+    void detach() {
+        auditLogger.detachAppender(appender);
+    }
+
+    private JsonNode onlyRecord() throws Exception {
+        assertEquals(1, appender.list.size(), "exactly one audit line expected");
+        String line = appender.list.getFirst().getFormattedMessage();
+        return mapper.readTree(line); // throws if the line is not valid JSON
+    }
+
+    @Test
+    void anAllowedActionIsRecordedAsValidJson() throws Exception {
+        AuditLog.allowed(Principal.primary(4242), Authz.Action.SPAWN, "term_a");
+
+        JsonNode r = onlyRecord();
+        assertEquals("PRIMARY", r.path("role").asText());
+        assertEquals("primary", r.path("actor").asText());
+        assertEquals(4242, r.path("pid").asLong());
+        assertEquals("SPAWN", r.path("action").asText());
+        assertEquals("term_a", r.path("target").asText());
+        assertEquals("allowed", r.path("outcome").asText());
+        assertFalse(r.path("ts").asText().isBlank(), "every record carries its own timestamp");
+    }
+
+    @Test
+    void aDenialRecordsTheReason() throws Exception {
+        AuditLog.denied(Principal.worker("term_b", 7), Authz.Action.REPLY, "term_a", "forbidden");
+
+        JsonNode r = onlyRecord();
+        assertEquals("WORKER", r.path("role").asText());
+        assertEquals("worker:term_b", r.path("actor").asText());
+        assertEquals("denied", r.path("outcome").asText());
+        assertEquals("forbidden", r.path("reason").asText());
+    }
+
+    @Test
+    void aNullCallerIsRecordedAsAnonymousRatherThanCrashing() throws Exception {
+        AuditLog.failed(null, Authz.Action.SEND, null, "herdr unreachable");
+
+        JsonNode r = onlyRecord();
+        assertEquals("ANONYMOUS", r.path("role").asText());
+        assertTrue(r.path("target").isNull(), "an absent target is JSON null, not the string \"null\"");
+        assertEquals("failed", r.path("outcome").asText());
+    }
+
+    @Test
+    void hostileValuesAreEscapedAndCannotForgeAnExtraRecord() throws Exception {
+        // A target id containing a quote and a newline must not be able to terminate the JSON
+        // object early and inject a second, attacker-shaped audit line.
+        AuditLog.denied(Principal.worker("term_a", 1), Authz.Action.REPLY,
+                "evil\",\"outcome\":\"allowed\"}\n{\"forged\":true", "forbidden");
+
+        JsonNode r = onlyRecord();
+        assertEquals("denied", r.path("outcome").asText(),
+                "the injected outcome must not override the real one");
+        assertTrue(r.path("target").asText().contains("forged"),
+                "the hostile text survives as inert data inside the target field");
+    }
+}