Files
personaEngine2/docs/Logging.md
T
dave 5f125c34f2 Add elapsed run time, per-account results CSV, and a default config path
Summaries now show elapsed wall-clock time since the run started, and every
summary (interim and final) overwrites a results.csv (Object ID, UPN,
persona/status) next to the audit log, so an operator has a plain export
without parsing NDJSON. ConfigPath also now defaults to
./config/persona-engine.json instead of requiring -ConfigPath every run.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
2026-08-24 22:10:24 -04:00

149 lines
7.1 KiB
Markdown

# Logging
Structured audit output: what is emitted, where it goes, and what may never appear in it.
The serialized contract is [audit-record.md](../specs/001-persona-engine/contracts/audit-record.md).
This document covers the operational side.
## Format and transport
Newline-delimited JSON (OTD-006). One record per line, UTF-8 without BOM, appended.
Every record passes through a single sink, `Write-PersonaAuditRecord`. Adding a transport — an
approved logging platform, an event hub, a different file layout — is a change to that one function.
If call sites wrote their own output, each new transport would mean auditing every call site again,
and the one that got missed would be silent.
| `logging.destination` | Behaviour |
| --- | --- |
| `file` | Appends NDJSON to `logging.path` |
| `stream` | Emits the record object on the PowerShell **Information** stream |
| `both` | Both |
| `none` | Nothing |
`logging.path` is optional. When it (and `-OutputPath`) are unset, `file`/`both` write to
`<current-directory>/logs/persona-engine-audit.ndjson`, created on first write.
`stream` uses the Information stream rather than the success stream deliberately. Audit records on
the success stream would be indistinguishable from a function's return value — the run loop returns
its outcome there — and mixing the two turns one object into an array of several thousand. Capture
them with `-InformationVariable`, or redirect with `6>`.
### Sink failure never ends a run
A full disk or a locked file is an operational problem with the sink, not a reason to abandon a
classification run mid-population and leave the directory half-reconciled. The failure surfaces as a
warning, **once** per run, and processing continues.
Once, not once per user: a run over five thousand accounts with a locked log file should warn once,
or the warning that matters is buried in the noise it generates.
## Results CSV
Alongside the NDJSON audit log, every summary — interim and final — (re)writes a plain CSV listing
every account processed so far: `AccountObjectId`, `UserPrincipalName`, `PersonaStatus` (the assigned
persona for `Matched` accounts, otherwise `Unclassified` or `EvaluationError`). It is overwritten in
full each time, not appended, so it always reflects the whole run to that point rather than only the
accounts since the last summary.
It is written next to the audit log — same directory as `logging.path` — under `logging.resultsFileName`
(default `results.csv`). Export failure never ends a run, for the same reason a sink failure doesn't:
a locked file or full disk is an operational problem, not a reason to abandon a classification run
mid-population.
## Record types
| Type | When | Carries |
| --- | --- | --- |
| `RunStart` | Once, after mode is determined | Config path, target attribute, rule counts, whether tracing is on |
| `UserEvent` | Once per processed account | The full decision |
| `Summary` | Every `summaryInterval` accounts, and once at the end | Counters, per-rule match counts, reconciliation result |
| `RunComplete` | Once, in a `finally` block | Final counters, timing, exit code |
| `EngineDefect` | Reconciliation failure, or threshold breach | What went wrong and by how much |
`RunComplete` is written even on a fatal error. A run that died at account 400 of 5,000 leaves a
record saying exactly that — which is what lets an operator tell "the engine stopped early" from "the
engine never started", two very different incidents that produce identical evidence if the record is
written only on success.
## The common envelope
Every record, every type:
`timestamp` · `recordType` · `runId` · `engineVersion` · `configVersion` · `configurationHash` · `mode`
These appear **first** in each record, so a truncated line still identifies the run that produced it.
`runId` comes from `-CorrelationId` or is generated, and is constant for the run (NFR-005).
`configurationHash` is the SHA-256 of the configuration file bytes — two files differing only in
whitespace are different configurations for audit purposes, and the hash must be reproducible from
the artifact on disk.
## `UserEvent`
100% carry `runId`, `userPrincipalName`, and `accountObjectId` (SC-006). 100% of `Matched` records
carry `matchedRuleId`. `evaluationErrorReason` is non-null exactly when `outcome` is
`EvaluationError`.
`previousValue` is present **only** on `Updated` records, captured at write time. On any other action
there is nothing that was replaced, and a populated `previousValue` would imply otherwise to a
rollback tool reading these records later. Without it, OTD-010 rollback is impossible retroactively —
no future run can reconstruct what a value used to be.
## What may never appear
Access tokens, `Authorization` headers, client secrets, certificates, credentials, and full Graph
responses.
The guarantee is structural rather than filtered. `New-PersonaAuditRecord` accepts only named, typed
values from the decision result and the counters — there is no pass-through of an arbitrary object,
so there is nothing for a secret to ride in on, even if a caller attaches a token to the decision
result.
## Approved for logs
User principal name, account object ID, matched rule ID, stored and calculated persona values, run
ID, configuration version and hash, per-rule match counts, timing.
Runtime records naturally contain real UPNs and Object IDs. **No such value may ever be committed to
this repository** (SC-013) — the sanitization scan enforces that on every build.
## Condition tracing
`conditionTrace` is added to a `UserEvent` only when **both** gates are open: the decision result was
built with tracing, and the record was asked to include it. It carries the per-rule result
(`True` / `False` / `Unknown`) and priority.
Tracing widens what the log contains beyond the approved set, so it requires
`logging.acknowledgeConditionTracing` in the same configuration (`PE-SAF-006`). Tracing never changes
a decision — if it could, a debug run would stop being evidence about the real one.
## Querying
```powershell
# Everything from one run
Get-Content <LOG-OUTPUT-PATH> | ForEach-Object { $_ | ConvertFrom-Json } |
Where-Object runId -eq '<RUN-ID>'
# Accounts a run changed, with what it replaced
Get-Content <LOG-OUTPUT-PATH> | ForEach-Object { $_ | ConvertFrom-Json } |
Where-Object { $_.recordType -eq 'UserEvent' -and $_.action -eq 'Updated' } |
Select-Object userPrincipalName, previousValue, calculatedPersona, matchedRuleId
# Accounts that could not be evaluated, and why
Get-Content <LOG-OUTPUT-PATH> | ForEach-Object { $_ | ConvertFrom-Json } |
Where-Object outcome -eq 'EvaluationError' |
Select-Object userPrincipalName, evaluationErrorReason
# Which rule set produced a given decision
Get-Content <LOG-OUTPUT-PATH> | ForEach-Object { $_ | ConvertFrom-Json } |
Where-Object recordType -eq 'RunStart' |
Select-Object runId, configVersion, configurationHash, mode
```
## Retention
Not set by this engine. Records contain UPNs and Object IDs, so retention is governed by the
organization's identity-data policy rather than by anything in this repository. Decide it before the
first enforcing run, not after.