kevin
19cdf8dc9f
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.
101 lines
4.0 KiB
Java
101 lines
4.0 KiB
Java
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");
|
|
}
|
|
}
|