In short

Log each security decision as one structured event with a fixed name, a UTC timestamp, actor, target, tenant, outcome, reason and an operation ID that survives retries, and log the committed effect separately from the request. Encode events as JSON so user input cannot forge entries, redact credentials by path and test with canary values, ship events to a separate store, and map the fields to a standard such as ECS or OCSF.

  • A 200 response to POST /roles proves a response, not a role change; log the request, the decision and the committed effect, joined by an operation ID.
  • Log injection (CWE-117) needs an unencoded delimiter: in JSON lines a newline stays inside the string value.
  • Redaction covers only the paths you list: pino's *.token caught credentials.token but not a top-level token.
  • Keep the time an event happened and the time it was ingested as separate fields, and deduplicate on a sequence or operation ID.
  • OWASP Top 10:2025 names A09 Security Logging and Alerting Failures: events nobody alerts on do not count as detection.

Verify it

  1. Log a field containing \n{"event":"forged"} and confirm the output still has exactly one line for the event.
  2. Send canary credentials in every redacted path and at other nesting depths, then search the log store for them; expect no match.
  3. Make one allowed and one denied role change and confirm the accepted, committed and denied events carry the right operation IDs.
  4. Stop the log shipper in a test environment and confirm that an alert fires and the outbox keeps undelivered events.
  5. Confirm timestamps are UTC with an explicit offset and that the collector records its own ingestion time.
Applies to
  • pino 10.3.1 (redaction tested)
  • OCSF 1.9.0

Structured security events and investigation records. Logs need access controls, retention and reliable delivery.

Fix it in your stack

Tested fixes: the vulnerable code, the fix, a plausible fix that still fails, and the regression tests that tell them apart.

Learning goals and prerequisitesAbout 27 minutes: 7 to read and 20 for the exercise

What you will learn

  • Reconstruct a security event from attempted and committed actions
  • Design useful structured fields without logging credentials
  • Recognize evidence gaps caused by clocks, sampling and failed delivery

Before you start

Developers who add audit and security events to services, and the platform and security teams who collect and use them

  • Trace a request from identity verification to its authorization decision and resulting effect.

Refresh first: Enforce authorization for every object action

Go to the guided practice

Start from an investigation question

Choose the decisions responders need to reconstruct: who changed a role, why an authorization check failed, which session was revoked, or whether an export completed. Infrastructure access logs rarely explain all of these application decisions. Assign each event a clear meaning before adding more fields.

Use a consistent event vocabulary across services. Record an event type, timestamp, service/version, actor reference where appropriate, operation, target reference, outcome, reason category, and correlation identifier. Distinguish an attempted action from its successful completion so a request log is not mistaken for proof of a business effect.

Logs your customers cannot get do not help them. In the 2023 Storm-0558 intrusion, the only victim to detect it did so with a mailbox access log that required a premium licence, and other victims could not see past activity at all: /domains/identity-crypto/authentication/case-study-storm-0558/.

Worked investigation: did a permission change actually take effect?

An incident responder asks whether a support operator changed a customer’s role. An access log contains POST /roles with status 200. That line establishes an HTTP response, not the resulting authorization state: the handler may return before a worker commits, or the response may describe an accepted request. Define separate events for the request, policy decision and committed effect, and connect them with an operation identifier.

Use a stable actor reference from verified identity, a target reference, tenant, action, outcome and reason category. Add service revision and policy version so the responder can reconstruct which rule ran. In the example, operation op-41 was denied by tenant-policy-v8; op-42 was allowed and later committed. request_id changes on retries, while operation_id identifies one logical action. Neither identifier should be a bearer token or raw session cookie.

The record below intentionally avoids free-form request bodies. A malicious display name containing a newline remains data inside a JSON string rather than a forged second log entry; the fix card at /fix/crlf-log-injection/ covers plain-text logs. Even a structured logger needs bounded fields and safe downstream rendering: a spreadsheet export can interpret formula prefixes, and a web console can render HTML unsafely. The logging transport should preserve event boundaries and authenticity, not simply concatenate user input with text.

A durable audit event can be coordinated with a business transaction through an outbox: commit the role change and its pending audit record together, then deliver the audit record asynchronously with deduplication. This closes a particular gap between committed changes and lost logs. It does not prove the collector is immutable or that the actor was legitimate. Decide which operations must refuse to proceed when their required evidence cannot be persisted, rather than making every logging outage either fail-open or a site-wide denial of service.

JSON
{"event":"role_change.denied","operation_id":"op-41","actor":"support-7","tenant":"north","target":"south:user-9","reason":"tenant_boundary","policy":"tenant-policy-v8","service_revision":"r52"}
{"event":"role_change.accepted","operation_id":"op-42","actor":"support-7","tenant":"north","target":"north:user-3"}
{"event":"role_change.committed","operation_id":"op-42","actor":"support-7","tenant":"north","target":"north:user-3","old_role":"reader","new_role":"editor","audit_sequence":918}

Emit the events with a structured logger

The module below configures pino 10 for security events: one JSON object per line, UTC timestamps, service fields on every event, a fixed message per event name and redaction of the Authorization header, cookies, passwords and tokens. Logging the denied and committed role changes from the example produced exactly two lines, even though the display name contained a newline followed by a forged role_change.committed event: the newline was written as \n inside the JSON string. The bearer token and the nested token were replaced by [REDACTED].

Redaction is path-based. In the same test *.token matched credentials.token but not a top-level token or session.auth.token, both of which were logged in clear text. List every path, keep secrets out of event objects in the first place, and test with canary values at several depths.

Fixedaudit-log.mjsJavaScript
// Structured security events with pino 10: JSON lines, UTC timestamps and redaction of credentials.
import pino from 'pino';

export const audit = pino({
  base: {service: 'accounts', service_version: 'r52'},
  timestamp: pino.stdTimeFunctions.isoTime, // "time":"2026-10-10T09:00:00.000Z"
  redact: {
    paths: ['req.headers.authorization', 'req.headers.cookie', '*.password', '*.token'],
    censor: '[REDACTED]',
  },
});

// One event per decision; the message is a fixed event name, never user input.
export function roleChange(stage, fields) {
  audit.info({event: `role_change.${stage}`, ...fields}, `role_change.${stage}`);
}

Keep the event useful and bounded

  • Exclude passwords, bearer tokens, raw session identifiers, unnecessary personal data, and full sensitive request or response bodies.
  • Use structured logging and safely encode untrusted field values. Bound field lengths and prevent line breaks or delimiters from forging additional events.
  • Protect transport and storage, restrict access, monitor changes to collection, and define retention and disposal for the actual investigation need.
  • Maintain time synchronization and record collection delays. Do not silently sample away events essential to an audit or incident sequence.
  • Choose severity from context. A single rejected request is not automatically a critical incident; repeated or consequential patterns may deserve escalation.

Map the fields to ECS or OCSF

A common schema lets the SIEM correlate your security events with audit logs from other systems and the rest of your observability data. The Elastic Common Schema is being merged into the OpenTelemetry semantic conventions; OCSF is used by Amazon Security Lake and other security data platforms. The table maps the vocabulary of the worked example; in OCSF 1.9 a role change belongs to the User Management class, with activity 16, Assign Roles; the older User Access Management class is deprecated.

Map the fields to ECS or OCSF
Field in the exampleECSOCSF 1.9 (User Management, 3007)
event (role_change.committed)event.action, with event.category: iam and event.type: changeclass_uid 3007 and activity_id 16
Time the action happened@timestamptime
Time the collector received itevent.ingestedmetadata.logged_time
actoruser.idactor.user.uid
targetuser.target.iduser.uid
tenantorganization.idmetadata.tenant_uid
Outcome (allowed, denied)event.outcome: success or failurestatus_id: 1 Success or 2 Failure
reasonevent.reasonstatus_detail
operation_idtrace.id, or a custom fieldmetadata.correlation_uid
service_revisionservice.versionmetadata.product.version

Test the path to a human decision

Generate synthetic authentication, authorization, administrative-change, and revocation events in a test environment. Verify that each arrives with the correct meaning and can be correlated without exposing a secret. Include malicious-looking names, very long values, and unavailable log storage.

Confirm that logging failures have a deliberate service behavior and raise an operational signal without recursively flooding logs. Exercise one alert through acknowledgment and investigation, as the runtime detection and response guide at /domains/runtime/detection/runtime-detection-response/ describes. Preserve event definitions, example records, retention settings, and owners. A dashboard of collected bytes demonstrates ingestion; a responder answering the original investigation question demonstrates usefulness.

Diagnose incomplete fixes

Ordering solely by collector timestamps can reverse a real sequence when events are delayed or clocks disagree. Preserve event time and ingestion time, use operation IDs and supported sequence/transaction identifiers, and record clock uncertainty where it affects conclusions. Do not invent a precise order from timestamps with overlapping uncertainty.

High log volume is not the same as good detection. A denied request may be routine; a rare allowed privilege change may deserve stronger attention. Define which events must not be sampled, then test that a responder can answer one concrete question using retained records. Review who can delete, modify or disable collection and alert on changes to that path.

Check the result against concrete cases

These outcomes belong to the worked example; the logger test above covers the encoding and redaction rows, and the delivery rows need a test of your own collector.

Check the result against concrete cases
CaseExpected resultWhat it establishes
op-41 has only a denied eventNo role-change success establishedDecision outcome is explicit
op-42 accepted and committedCommit established for target north:user-3Business effect differs from request
Collector receives same sequence twiceOne logical audit event after deduplicationAt-least-once delivery handled
Missing sequence 919Investigate an evidence gapSilence is not a benign outcome
Raw Authorization field appearsFail log-sanitization checkSecrets are not evidence fields

Guided practice

Use a short event timeline to determine which account changed, which action was denied, and what cannot be concluded.

Supplied scenario material
Plain text
10:00:00 app: op-41 role_change.denied, target south:user-9, reason tenant_boundary.
10:00:01 app: op-42 role_change.accepted, target north:user-3.
10:00:03 app: op-42 role_change.committed, reader→editor, sequence 918.
10:00:02 collector time: receives sequence 918.
10:00:05 collector time: receives duplicate sequence 918.
Last known outbox sequence is 919; collector has no 919.
Proposed debug field: Authorization=Bearer SECRET-DEMO.
Clock note: app may be two seconds ahead of collector.
  1. 1. Separate attempt from effect

    Identify the operation that changed a role and the operation that did not establish a change.

    Expected result and reasoning

    op-42 has explicit commit evidence for north:user-3, changing reader to editor. op-41 records denial for south:user-9; the fixture contains no commit for that attempt. Merely seeing the denied target in a log is not evidence it was modified.

  2. 2. Deduplicate and order cautiously

    Count committed changes represented by the two collector deliveries and interpret the timestamp inversion.

    Expected result and reasoning

    Both deliveries have sequence 918 and operation op-42, so they represent one recorded commit. Collector 10:00:02 preceding app 10:00:03 is compatible with the stated clock skew; it does not demonstrate time travel or tampering.

  3. 3. Identify the unanswered question

    Explain what missing sequence 919 means and what to inspect next.

    Expected result and reasoning

    There is a delivery or retention gap. Inspect the durable outbox, relay retry state, collector acknowledgment and retention controls. The fixture does not reveal what 919 contains, so neither a second role change nor absence of one can be asserted.

  4. 4. Replace unsafe debugging

    Remove the proposed bearer field and name evidence that retains investigative usefulness.

    Expected result and reasoning

    Keep actor reference, authentication method/result category, operation ID, policy revision and redacted credential identifier if the design supports one. Do not retain the bearer value. If it has already been logged, treat its retained copies and credential validity as a separate exposure to remediate.

Your deliverable: A record that separates the denied attempt from the committed change, counts one commit despite duplicates, explains the missing sequence and replaces the unsafe debug field.

The timeline is supplied; the logger module and verification steps on this page show how to produce and test the same events in a service.

Save a draft on this device to resume later. Automatic saving begins after you choose Save. Drafts are never sent by this application; use synthetic data.

No draft saved on this device yet.

Sources & further reading

The standards, specifications and documentation behind the guidance above. Each is the evidence for a claim on this page; consult it for detail beyond the defaults and versions listed here.

  1. OWASP Logging
  2. OWASP Logging Vocabulary
  3. OWASP ASVS 5.0 V16 Security Logging and Error Handling. Version 5.0.0.
  4. OWASP Top 10:2025 A09 Security Logging and Alerting Failures
  5. CWE-117: improper output neutralization for logs. CWE version 4.20.
  6. pino: redaction
  7. Elastic Common Schema: event fields
  8. OCSF schema 1.9.0: User Management

Reference information

SDLC phase
Maintenance
ASVS 5.0.0 requirements
v5.0.0-16.2.1 · v5.0.0-16.2.5 · v5.0.0-16.3.2 · v5.0.0-16.4.1 · v5.0.0-16.4.3

Download this guide as Markdown