CB-505 fix: audit lines were not valid JSON

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.
2026-07-29 22:32:18 +07:00
parent 9daf1ec5ba
commit 19cdf8dc9f
3 changed files with 115 additions and 6 deletions
@@ -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");
+    }
+}