Security Logging: Who Accessed What, Decided How#

Authorization logic lives in code, but the trace of each decision lives in logs. A request arrives, a policy runs, a decision is made, and an object is read or written. That chain needs more than its outcome recorded; the decision itself needs a record.

Without it, incident review gets stuck on one question: was this access really checked, or did it pass around the check. This note describes a small event schema that makes authorization decisions observable. Actor, tenant, object, action, and decision meet in one record. Allowed and denied requests share the same format. What stays out of the log is part of the schema too.

The post-incident questions#

After an incident, the first questions are always the same. Who touched this object. In which tenant context.

Was it a read or a write. Which policy, at which version, allowed or denied it. The application database cannot answer these questions. It holds the current state of the object, not the history of access decisions. Without an access log, only guessing remains.

Which questions go unanswered#

Standard access logs usually keep URL and status code. That information does not answer authorization questions. A 200 response on /invoices/abc does not say which tenant filter was applied.

A 403 on the same URL does not say which role check failed. Without a request id, a frontend error cannot be joined to a backend decision. Without policy name and version, nobody knows which rule ran. These gaps share the same root as the silent flaws in the API access control test plan. The check exists in code, but no record exists to verify the decision later.

The team then faces the following table, which shows what each source can answer:

Log the allowed and the denied#

Logging only denied requests is a common gap. The reason is usually volume: allowed requests are many, and logs grow fast. But without allowed records, several questions stay open.

Which decision opened this object. Which actions did this user take on this object before. Was the tenant filter active on that day.

Without denied records, the attack signal disappears. The probing actor stays invisible. So the rule is simple: every authorization decision emits one event.

The format stays the same for allow and deny. Only the decision field differs. That symmetry makes testing easier too.

A test for the allowed path expects an allow event. A test for the denied path expects a deny event. Since the shape never changes, both tests use the same assertion helper.

The decision is made in the policy layer and logged there#

When authorization logic is scattered, logging scatters with it. if checks spread across actions produce scattered log calls. One is forgotten, one uses a different shape, one writes nothing.

The fix is to collect the decision in one function. The policy function makes the decision and emits the record. Action functions only use the policy result.

That split protects log completeness through code structure. When a new action is added, the developer does not think about log shape. The action calls the policy function, and the log follows automatically. When the shape changes, one place is updated.

Event schema and one helper#

The schema stays small, and every field has a clear job.

The TypeScript event type#

The type below locks the canonical fields. Optional fields travel in separate detail slots, while core fields stay required on every event.

Copy code
// lib/authz/authz-log.ts
export type AuthzDecision = 'allow' | 'deny';

export type AuthzAction = 'read' | 'write' | 'admin';

export interface AuthzEvent {
  timestamp: string;
  actorId: string;
  sessionId: string;
  tenantId: string;
  objectType: 'invoice' | 'project' | 'document' | 'member';
  objectId: string;
  objectTenantId: string;
  action: AuthzAction;
  decision: AuthzDecision;
  policyName: string;
  policyVersion: string;
  requestId: string;
  denyReason?: string;
  latencyMs?: number;
}

denyReason is filled only on deny events. Allow events leave it empty, which keeps allow records small. latencyMs shows the cost of the policy check. Slow queries surface through this field.

One canonical helper#

One write path keeps the shape intact. Every policy in the codebase calls this helper. The helper refuses calls with missing fields.

Copy code
// lib/authz/authz-log.ts
import { authzLogger } from './authz-logger';

export function logAuthzEvent(event: AuthzEvent): void {
  authzLogger.info({
    type: 'authz.decision',
    timestamp: event.timestamp,
    actorId: event.actorId,
    sessionId: event.sessionId,
    tenantId: event.tenantId,
    objectType: event.objectType,
    objectId: event.objectId,
    objectTenantId: event.objectTenantId,
    action: event.action,
    decision: event.decision,
    policyName: event.policyName,
    policyVersion: event.policyVersion,
    requestId: event.requestId,
    denyReason: event.denyReason,
    latencyMs: event.latencyMs,
  });
}

export function buildAuthzTimestamp(now: Date = new Date()): string {
  return now.toISOString();
}

The type field is a fixed string. That constant keeps search queries simple. Search starts with type:authz.decision, then adds filters like decision:deny.

The helper hides transport detail. Which log library sits below does not matter to callers. JSON lines are used, so each line parses on its own.

Call from the policy layer#

The policy function both decides and records. Success and failure paths each emit a log. Every early return writes its own event.

Copy code
// lib/actions/policy.ts
import { auth } from '@/lib/auth';
import { db } from '@/lib/db';
import { buildAuthzTimestamp, logAuthzEvent } from '@/lib/authz/authz-log';

const POLICY_NAME = 'invoice-access';
const POLICY_VERSION = 'v3';

export async function requireInvoiceAccess(
  invoiceId: string,
  action: 'read' | 'write',
  requestId: string,
) {
  const startedAt = Date.now();
  const session = await auth();

  if (!session) {
    logAuthzEvent({
      timestamp: buildAuthzTimestamp(),
      actorId: 'anonymous',
      sessionId: 'none',
      tenantId: 'unknown',
      objectType: 'invoice',
      objectId: invoiceId,
      objectTenantId: 'unknown',
      action,
      decision: 'deny',
      policyName: POLICY_NAME,
      policyVersion: POLICY_VERSION,
      requestId,
      denyReason: 'no-session',
      latencyMs: Date.now() - startedAt,
    });
    throw new Error('Not found');
  }

  const invoice = await db.invoice.findFirst({
    where: {
      id: invoiceId,
    },
    select: {
      id: true,
      tenantId: true,
    },
  });

  if (!invoice) {
    logAuthzEvent({
      timestamp: buildAuthzTimestamp(),
      actorId: session.user.id,
      sessionId: session.sessionId,
      tenantId: session.tenantId,
      objectType: 'invoice',
      objectId: invoiceId,
      objectTenantId: 'unknown',
      action,
      decision: 'deny',
      policyName: POLICY_NAME,
      policyVersion: POLICY_VERSION,
      requestId,
      denyReason: 'object-not-found-or-hidden',
      latencyMs: Date.now() - startedAt,
    });
    throw new Error('Not found');
  }

  if (invoice.tenantId !== session.tenantId) {
    logAuthzEvent({
      timestamp: buildAuthzTimestamp(),
      actorId: session.user.id,
      sessionId: session.sessionId,
      tenantId: session.tenantId,
      objectType: 'invoice',
      objectId: invoice.id,
      objectTenantId: invoice.tenantId,
      action,
      decision: 'deny',
      policyName: POLICY_NAME,
      policyVersion: POLICY_VERSION,
      requestId,
      denyReason: 'tenant-mismatch',
      latencyMs: Date.now() - startedAt,
    });
    throw new Error('Not found');
  }

  const membership = await db.membership.findFirst({
    where: {
      userId: session.user.id,
      tenantId: session.tenantId,
    },
    select: {
      role: true,
    },
  });

  const allowedRoles = action === 'write'
    ? ['owner', 'finance']
    : ['owner', 'finance', 'viewer'];

  if (!membership || !allowedRoles.includes(membership.role)) {
    logAuthzEvent({
      timestamp: buildAuthzTimestamp(),
      actorId: session.user.id,
      sessionId: session.sessionId,
      tenantId: session.tenantId,
      objectType: 'invoice',
      objectId: invoice.id,
      objectTenantId: invoice.tenantId,
      action,
      decision: 'deny',
      policyName: POLICY_NAME,
      policyVersion: POLICY_VERSION,
      requestId,
      denyReason: 'insufficient-role',
      latencyMs: Date.now() - startedAt,
    });
    throw new Error('Not found');
  }

  logAuthzEvent({
    timestamp: buildAuthzTimestamp(),
    actorId: session.user.id,
    sessionId: session.sessionId,
    tenantId: session.tenantId,
    objectType: 'invoice',
    objectId: invoice.id,
    objectTenantId: invoice.tenantId,
    action,
    decision: 'allow',
    policyName: POLICY_NAME,
    policyVersion: POLICY_VERSION,
    requestId,
    latencyMs: Date.now() - startedAt,
  });

  return { invoice, session };
}

Every deny path returns the same error. From outside, an unauthorized resource and a missing resource look alike. Inside the log, the deny reason stays explicit.

That split builds closed outside, open inside behavior. This pattern continues the single-policy idea from the Server Actions authorization note. The decision is made in one place, the record is written in one shape.

Field dictionary#

The schema table fixes the expected values per field. A newcomer can read logs from this table alone.

What stays out#

A security log does not record everything. Some values turn the log itself into a risk when written. This section draws that boundary.

Secrets and tokens are never written#

Passwords, API keys, session tokens, and signature values never enter the log. The authorization decision may depend on these values, but the values themselves stay out of the record. Debugging comfort never softens this rule.

Writing a token to the log hands session replay to everyone with log access. So the helper accepts no secret fields. Since the type has no room for them, writing one by accident gets harder.

Logging the full request body carries the same risk. A body may hold a password or a token. Only the ids needed for the decision are written, the rest of the body is not.

Keep personal data minimal#

Personal data stays limited to identity. The user id is written, the user profile is not. Email, phone, and address fields have no place in an authorization event.

Invoice line items, document text, and file names stay out as well. The record describes access, not content. That split follows purpose limitation in a natural way.

The purpose of the log is to verify access decisions after the fact. An object id is enough for that purpose, object content is not needed. When content is needed, it is read from the database under a separate permission.

Write down purpose and lifetime#

Every log has a purpose and a lifetime. The purpose of the authorization log is written down: verify access decisions later and expose probing signals. Uses outside that purpose need a separate review for the same data.

Using the authorization log for product analytics, for example, widens the purpose. Such a need calls for a separate event type and a separate approval. Retention is fixed up front too.

Hot storage keeps a short window, warm storage keeps a longer one. Expired records are deleted or anonymized. That rule matters for data protection as much as for volume. Less data, shorter lifetime, and narrow access apply together.

The table below makes the choice fast:

Denied requests as attack signal#

Deny records are not debug output. Repeated denies may show someone testing doors. One deny is normal: a wrong link, an expired share, a changed role. Many denies from the same actor in a short window are not normal.

Attack patterns#

The patterns sought in deny logs are known. Each pattern describes a different probing behavior.

Threshold design#

An alert rule has three parts. A counter, a window, and an action. The counter says which events count. The window says over what time they count. The action says what happens when the limit is passed.

Copy code
// lib/authz/authz-alerts.ts
export interface DenyThreshold {
  name: string;
  windowSeconds: number;
  maxDenies: number;
  groupBy: 'actorId' | 'sessionId' | 'objectType';
  denyReasons: Array<string>;
}

export const DENY_THRESHOLDS: Array<DenyThreshold> = [
  {
    name: 'actor-probing',
    windowSeconds: 300,
    maxDenies: 20,
    groupBy: 'actorId',
    denyReasons: ['tenant-mismatch', 'object-not-found-or-hidden'],
  },
  {
    name: 'write-escalation',
    windowSeconds: 600,
    maxDenies: 10,
    groupBy: 'actorId',
    denyReasons: ['insufficient-role'],
  },
  {
    name: 'anonymous-scan',
    windowSeconds: 300,
    maxDenies: 30,
    groupBy: 'sessionId',
    denyReasons: ['no-session', 'object-not-found-or-hidden'],
  },
];

The counter function counts denies for one grouping key. It resets when the window passes. When the limit is passed, an alert is emitted; requests are not blocked automatically. Automatic blocking is a separate decision, a log rule alone never blocks.

Copy code
// lib/authz/authz-alerts.ts
export function isThresholdExceeded(
  events: Array<{ timestamp: string; denyReason?: string }>,
  threshold: DenyThreshold,
  now: Date = new Date(),
): boolean {
  const windowStart = now.getTime() - threshold.windowSeconds * 1000;
  let count = 0;

  for (const event of events) {
    const eventTime = Date.parse(event.timestamp);
    if (Number.isNaN(eventTime)) {
      continue;
    }
    if (eventTime < windowStart) {
      continue;
    }
    if (event.denyReason && threshold.denyReasons.includes(event.denyReason)) {
      count += 1;
    }
  }

  return count >= threshold.maxDenies;
}

This function stays pure, with no outside dependency. It takes an event list and returns the threshold call. Time arrives as a parameter, which keeps tests simple. In production the event list comes from the log store.

Tuning against false positives#

Thresholds never stay at first values. The first week is observation: count alerts, separate real probing from noise. False positive sources are usually the same.

A wrongly saved bookmark produces repeated denies on one record. A user with a changed role refreshes an old page and builds a deny series. A support agent tries to open a record for a customer and emits tenant mismatch.

An old mobile build calls a retired action and emits role denies. Three settings handle these cases. An allow list: known service accounts are watched with a separate threshold.

Graded limits: an info alert fires first, a review alert fires later. Context enrichment: the alert carries the last five object types and deny codes. Alert text stays short but carries enough for review. Actor, window, deny count, dominant deny code, and sample requestId values are enough. The reviewer starts from there and moves deeper in the log store.

Storage and access#

The authorization log lives in a separate store. It never shares tables with the application database. Separation serves two aims. One is access control, the other is tamper resistance.

Who can read#

Read access stays narrow. A small review group reads for security work. The product team may see aggregate counts but not per-actor records.

The support team may see records for one requestId but may not scan. That split is enforced in tooling, not only in policy text. The log store has role-based access, so not everyone can run the same query.

Fewer people with production data access means a smaller leak surface. Reads themselves are recorded. Who read the log and which query ran leaves a separate trail. That trail stays apart from the authorization log, never mixed in.

Hot and warm tiers#

Retention uses two tiers. The hot tier serves fast search and keeps a short window. The warm tier serves backward review and keeps a longer one.

Keeping everything in archive breaks alerting. Movement rules run automatically. Expired records move from hot to warm on schedule. Records expired in warm storage are deleted or have id fields masked. Delete and mask operations are recorded as well.

Tamper-evidence basics#

The authorization log is append-only. Existing lines are never updated or deleted. When a fix is needed, a new line is written and the old line stays.

The store is separate and never shares write permission with the app. The app holds append permission only; it holds no read or delete permission on the log. That split makes bulk change hard even when one account is taken over.

Simple checks are enough for integrity. Each line may carry a chain hash, or the store may turn on immutability. The aim is not court-grade proof.

The aim is to stop an ordinary error or a single account from quietly rewriting history. Backups follow the same rule. A backup restore never overwrites the live log. Restores go to a separate area, and merge rules are written down.

Testing logs#

Log claims are guarded by tests. Without tests, the shape rots over time. Someone adds a new deny path and forgets the log call. Someone changes an error message and turns a reason code into free text. Matrix tests catch that drift.

Did a deny event get emitted#

The helper below reads an in-memory log store. The test runs the operation, then checks the stored event.

Copy code
// test/authz-log-assert.ts
import type { AuthzEvent } from '@/lib/authz/authz-log';

export function findAuthzEvents(
  events: Array<AuthzEvent>,
  filter: Partial<AuthzEvent>,
): Array<AuthzEvent> {
  return events.filter((event) => {
    for (const [key, value] of Object.entries(filter)) {
      if ((event as Record<string, unknown>)[key] !== value) {
        return false;
      }
    }
    return true;
  });
}

export function expectDenyLogged(
  events: Array<AuthzEvent>,
  expected: {
    actorId: string;
    tenantId: string;
    objectId: string;
    action: 'read' | 'write' | 'admin';
    denyReason: string;
    requestId: string;
  },
): void {
  const matches = findAuthzEvents(events, {
    actorId: expected.actorId,
    tenantId: expected.tenantId,
    objectId: expected.objectId,
    action: expected.action,
    decision: 'deny',
    requestId: expected.requestId,
  });

  if (matches.length !== 1) {
    throw new Error(
      `Expected one deny event, found ${matches.length} for request ${expected.requestId}`,
    );
  }

  if (matches[0].denyReason !== expected.denyReason) {
    throw new Error(
      `Expected deny reason ${expected.denyReason}, found ${matches[0].denyReason}`,
    );
  }
}

export function expectAllowLogged(
  events: Array<AuthzEvent>,
  expected: {
    actorId: string;
    tenantId: string;
    objectId: string;
    objectTenantId: string;
    action: 'read' | 'write' | 'admin';
    requestId: string;
  },
): void {
  const matches = findAuthzEvents(events, {
    actorId: expected.actorId,
    tenantId: expected.tenantId,
    objectId: expected.objectId,
    action: expected.action,
    decision: 'allow',
    requestId: expected.requestId,
  });

  if (matches.length !== 1) {
    throw new Error(
      `Expected one allow event, found ${matches.length} for request ${expected.requestId}`,
    );
  }

  if (matches[0].objectTenantId !== expected.objectTenantId) {
    throw new Error('Allow event tenant does not match object tenant');
  }

  if (matches[0].tenantId !== matches[0].objectTenantId) {
    throw new Error('Allow event shows cross-tenant access');
  }
}

expectDenyLogged checks three things. The right actor, the right object, and the right reason code meet in one event. The event count is exactly one, neither zero nor two.

expectAllowLogged adds two checks. The object tenant id matches the expected value. The request tenant id matches the object tenant id. These two checks stop cross-tenant allows from passing unseen in logs.

Log assertions inside the matrix tests#

The authorization matrix already tests access outcomes. The same matrix gains log assertions; no separate test file is opened. Each row checks both the function outcome and the log event.

Copy code
// test/invoice-authz-matrix.test.ts
import { requireInvoiceAccess } from '@/lib/actions/policy';
import { getTestEvents, clearTestEvents } from '@/test/test-logger';
import { expectAllowLogged, expectDenyLogged } from '@/test/authz-log-assert';

describe('invoice authorization matrix with log assertions', () => {
  beforeEach(() => {
    clearTestEvents();
  });

  it('owner can read own-tenant invoice and logs allow', async () => {
    const requestId = 'req-matrix-001';
    await requireInvoiceAccess('inv_10021', 'read', requestId);

    expectAllowLogged(getTestEvents(), {
      actorId: 'user_owner_1',
      tenantId: 'tenant_acme',
      objectId: 'inv_10021',
      objectTenantId: 'tenant_acme',
      action: 'read',
      requestId,
    });
  });

  it('viewer cannot write and logs insufficient-role', async () => {
    const requestId = 'req-matrix-002';
    await expect(
      requireInvoiceAccess('inv_10021', 'write', requestId),
    ).rejects.toThrow('Not found');

    expectDenyLogged(getTestEvents(), {
      actorId: 'user_viewer_1',
      tenantId: 'tenant_acme',
      objectId: 'inv_10021',
      action: 'write',
      denyReason: 'insufficient-role',
      requestId,
    });
  });

  it('member of tenant A cannot read tenant B invoice', async () => {
    const requestId = 'req-matrix-003';
    await expect(
      requireInvoiceAccess('inv_90001', 'read', requestId),
    ).rejects.toThrow('Not found');

    expectDenyLogged(getTestEvents(), {
      actorId: 'user_owner_1',
      tenantId: 'tenant_acme',
      objectId: 'inv_90001',
      action: 'read',
      denyReason: 'tenant-mismatch',
      requestId,
    });
  });

  it('unknown invoice logs hidden-object deny without leaking', async () => {
    const requestId = 'req-matrix-004';
    await expect(
      requireInvoiceAccess('inv_missing', 'read', requestId),
    ).rejects.toThrow('Not found');

    expectDenyLogged(getTestEvents(), {
      actorId: 'user_owner_1',
      tenantId: 'tenant_acme',
      objectId: 'inv_missing',
      action: 'read',
      denyReason: 'object-not-found-or-hidden',
      requestId,
    });
  });
});

As the matrix grows, this pattern stays the same. Each row uses a fresh request id, so events never mix. A failed call leaks nothing outside, but carries the reason code inside the log. That split matters most in BOLA work, where hidden-object responses must still leave a precise trail. The matrix idea here matches the automation approach in the EN BOLA companion work only through shared test shape, and the primary text stays self-contained.

Schema test#

The shape itself is tested too. A schema test checks that required fields are filled and closed lists are respected.

Copy code
// test/authz-log-schema.test.ts
import type { AuthzEvent } from '@/lib/authz/authz-log';

const ALLOWED_REASONS = [
  'no-session',
  'object-not-found-or-hidden',
  'tenant-mismatch',
  'insufficient-role',
];

export function assertAuthzSchema(event: AuthzEvent): void {
  const required = [
    'timestamp',
    'actorId',
    'sessionId',
    'tenantId',
    'objectType',
    'objectId',
    'objectTenantId',
    'action',
    'decision',
    'policyName',
    'policyVersion',
    'requestId',
  ];

  for (const field of required) {
    const value = (event as Record<string, unknown>)[field];
    if (typeof value !== 'string' || value.length === 0) {
      throw new Error(`Authz event field ${field} is missing or empty`);
    }
  }

  if (Number.isNaN(Date.parse(event.timestamp))) {
    throw new Error('Authz event timestamp is not parseable');
  }

  if (event.decision === 'deny') {
    if (!event.denyReason || !ALLOWED_REASONS.includes(event.denyReason)) {
      throw new Error('Deny event needs a known deny reason');
    }
  }

  if (event.decision === 'allow' && event.denyReason) {
    throw new Error('Allow event must not carry a deny reason');
  }
}

This test runs on every event. When a field is added, the test is updated. Anyone tempted to write free-text reasons trips on this test.

Limitations#

Logs fix no problem on their own, and they bring their own cost. Knowing these limits keeps the schema in the right place.

Volume cost#

One event per decision means event count grows with request count. In a read-heavy product, allow events dominate. Storage and query cost rise with them.

Three moves balance that cost. The hot tier stays short, and old records move to warm storage. Allow events stay small, with no extra detail field.

Sampling gets a separate review for read-heavy endpoints. A sampling choice never breaks the schema; it only means some allow events are skipped. But sampled logs answer post-incident questions with gaps. So sampling is documented openly when used, and deny events stay outside sampling. Every deny is written, because signal value is high and volume is low.

Clock skew#

In split services, clocks never match exactly. Order of events from two services may mix at millisecond detail. That mixing makes timestamp alone a weak ordering key.

The fix is to avoid tying order to one clock and to join on requestId instead. Events from one request join on requestId, with no regard to clock. Cause and effect across events builds on that id.

Time sync stays at infrastructure level. Application code never applies its own clock correction. The log helper writes time at creation and never rewrites it later.

Sampling trade-offs#

Some teams sample allow events to cut volume. One in ten allow events is written, for example. That choice lowers query cost but opens a review gap.

In sampled logs, these questions stay thin. How often did this user reach this object this week. Which decisions opened this object.

Was the tenant filter active on a given day. So sampling is never the default. The default writes every decision. Sampling opens only after volume is measured and written down. Even then, denies, admin operations, and cross-tenant attempts are always written.

Short result#

While authorization decisions stay invisible, incident review rests on guessing. A small schema closes that gap: actor, tenant, object, action, decision, policy version, and request id meet on one line. Secrets and content stay out, ids and decisions stay in. Deny records turn into attack signal, allow records turn into access history. Tests confirm that every decision emits the right event.