Error Messages and Log Leakage

The previous lesson counted the trace a secret leaves in the source tree and in repository history. That trace closes once the value is pulled out of the source and moved into a store — but the value still sits in the process at run time, and the process talks. The response that comes back when a request errors, the log line written when an operation runs, the stack trace that lands in a file after a crash: all of these are points where values inside the process leak out.

What these points have in common is that none of them was written as a security decision. The line that puts the stack trace into the response is there to debug; the line that writes the request to the log with all its fields is there to find a problem. The measure, then, is not “which line is wrong” but the question of how many items leak out and how many of them a central layer closes.

Items in the Error Response

SC10 — an error response is the sum of the items that carry internal application information; each item is counted separately. A stack trace, an internal file path, an internal component name, the error class’s name, and the echo of the raw request are five separate items, and a single response can carry all of them at once. SC11 — a central error handler only covers the error that reaches it; an endpoint that catches its own error and writes its own response falls outside its coverage.

// log/response.mjs — a real local server is started, requests are sent to eight endpoints, and
// the internal-information items carried in the returned response body are counted. Bodies are not
// printed (they contain an absolute path); only item counts are written. The two endpoints marked
// "own" catch their own error and write their own response, so they never reach the central
// handler. Fictional measurement-network endpoints.
import { createServer } from 'node:http';
import { randomUUID } from 'node:crypto';

// [path, function that throws the error, whether it writes its own response]
const ENDPOINTS = [
  ['/subscriber/search?name=fictional-subscriber-118', () => { throw new Error('subscriber-directory/search.mjs: directory response empty'); }, false],
  ['/invoice/account?no=118', () => { throw new RangeError('invoice-account/period.mjs: period out of range'); }, false],
  ['/measurement/get?meter=MTR-4417', () => { throw new TypeError('measurement-ingestion/packet.mjs: field expected'); }, true],
  ['/report/generate?type=monthly', () => { throw new Error('report-generator/template.mjs: template not found'); }, false],
  ['/work-order/assign?team=3', () => { throw new Error('work-order/assignment.mjs: team capacity exceeded'); }, false],
  ['/field/upload?name=measurement.csv', () => { throw new Error('field-upload/storage.mjs: storage response invalid'); }, true],
  ['/portal/login?user=fictional-subscriber-118', () => { throw new Error('portal-identity/verify.mjs: comparison failed'); }, false],
  ['/notification/send?channel=sms', () => { throw new Error('notification-queue/send.mjs: queue full'); }, false],
];

let mode = 'direct';
const server = createServer((req, res) => {
  const endpoint = ENDPOINTS.find(([u]) => u === req.url);
  try {
    endpoint[1]();
  } catch (err) {
    const open = mode === 'direct' || (mode === 'central' && endpoint[2]);
    const body = open
      ? { error: err.message, type: err.constructor.name, trace: err.stack, request: req.url }
      : { error: 'operation could not complete', id: randomUUID() };
    res.writeHead(500, { 'content-type': 'application/json' });
    res.end(JSON.stringify(body));
  }
});
server.listen(8794, '127.0.0.1');

const MARKERS = [
  ['stack trace', (g) => /\bat\s+\S+\s*\(/.test(g)],
  ['internal file path', (g) => /\.mjs/.test(g)],
  ['internal component name', (g) => /(subscriber-directory|invoice-account|measurement-ingestion|report-generator|work-order|field-upload|portal-identity|notification-queue)/.test(g)],
  ['error class', (g) => /"type":"(Error|RangeError|TypeError)"/.test(g)],
  ['request echo', (g) => /"request":/.test(g)],
  ['correlation id', (g) => /"id":/.test(g)],
];

const write = (g, ...s) => console.log(s.map((v, i) =>
  (g[i] < 0 ? String(v).padEnd(-g[i]) : String(v).padStart(g[i]))).join(''));
const D = [-26, 13, 21, 26, 13, 14, 16];
write(D, 'mode', ...MARKERS.map(([a]) => a));

for (const m of ['direct', 'central', 'own response disabled']) {
  mode = m === 'own response disabled' ? 'closed' : m;
  const counter = MARKERS.map(() => 0);
  for (const [path] of ENDPOINTS) {
    const body = await (await fetch(`http://127.0.0.1:8794${path}`)).text();
    MARKERS.forEach(([, rule], i) => { if (rule(body)) counter[i] += 1; });
  }
  write(D, m, ...counter);
}
server.close();

const item = MARKERS.length - 1;
const own = ENDPOINTS.filter((u) => u[2]).length;
console.log(`\nendpoints ${ENDPOINTS.length}, items measured per response ${item}, `
  + `item-response pairs in direct mode ${ENDPOINTS.length * item}`);
console.log(`central handler covers ${ENDPOINTS.length - own} endpoints, ${own} endpoints stay uncovered; `
  + `uncovered item-response pairs ${own * item}`);

mode                        stack trace   internal file path   internal component name  error class  request echo  correlation id
direct                                8                    8                         8            8             8               0
central                               2                    2                         2            2             2               6
own response disabled                 0                    0                         0            0             0               8

endpoints 8, items measured per response 5, item-response pairs in direct mode 40
central handler covers 6 endpoints, 2 endpoints stay uncovered; uncovered item-response pairs 10

The Endpoint That Bypasses the Center

The first row is the measure’s starting point: all eight of the eight endpoints carry all five of the five items, which comes to 40 item-response pairs. This is the state where no one made a decision — the error object was written straight into the response as it is, and the stack trace tells the server’s file layout, the error class tells its internal logic, and the raw request echo tells that the sent value comes back.

The second row gives the central handler’s coverage, and it is the clearest example of the course’s rule. Six of the eight endpoints are covered, the item count drops to zero, and a correlation id takes its place. The remaining two endpoints — the measurement-ingestion endpoint and the field-upload endpoint — catch their own error and write their own response, so they never reach the central handler at all. On these two endpoints all five of the five items still stand: the number of uncovered pairs is 10. Coverage has dropped from 40 to 10, not to zero.

The distinction here matters: the central handler is not flawed, it works flawlessly on the six endpoints it covers. What lowers coverage is not the handler’s quality but the fact that it can be bypassed. An endpoint that writes its own error response mostly looks like a good habit in review — handling the error where it happens. The third row writes the rule: once local response writing is disabled, all eight of the eight endpoints drop down to the correlation id and the items left outside become zero.

The correlation-id column also carries this arrangement’s cost. The five items pulled out of the response do not disappear; they get tied to an id and carried inward. In a troubleshooting search, that id leads to the internal record, and the stack trace is found there. What the measure says is that the leak is not closed, only relocated: the response is open to eight clients, the internal record to a specific set of readers. The second measurement counts exactly this relocated pile itself, because a log is kept longer than a response and copied to more places.

Items in the Log Line

The response goes outward, the log stays inward — but the log too gets written somewhere, moved somewhere, and mostly kept longer than the response. SC12 — a masking layer works by looking at the field name; a value sitting where there is no name is not closed off by any name list.

// log/masking.mjs — the masking layer's coverage over fictional log records (model).
// Values are fictional; none of them is a real secret format or a real person's data.
const T = 'fictionaltoken7f2a9c41d8b3e6';
const IMZA = 'fictionalsignature4b7d2e9a1c8f5306';
const P = 'fictional-password-9c1x', AD = 'A. Smith', ADRES = 'Example St. 12/4';
const TEL = '05000000000', KN = '10000000146';

// [record, list of sensitive values that appear in that record, leak type]
const records = [
  [{ event: 'login', user: 'fictional-subscriber-118', token: T }, [T], 'top-level field'],
  [{ event: 'registration', subscriber: { subscriberName: AD, address: ADRES } }, [AD, ADRES], 'nested field'],
  [{ event: 'error', message: `validation failed: ${P}` }, [P], 'free text'],
  [{ event: 'request', target: `/portal/login?token=${T}` }, [T], 'query string'],
  [{ event: 'batch', records: [{ phone: TEL }, { nationalId: KN }] }, [TEL, KN], 'array item'],
  [{ event: 'sync', parent: T }, [T], 'name not in list'],
  [{ event: 'refresh', context: { session: { signature: IMZA } } }, [IMZA], 'third level'],
  [{ event: 'notification', subscriberName: AD, phone: TEL }, [AD, TEL], 'top-level field'],
];
const HARMLESS = ['a1b2c3d4e5f60718293a4b5c6d7e8f90', '9f3c2a1b8d7e6540c9b2a1f0e3d4c5b6'];
const harmlessRecords = [{ event: 'tracing', requestId: HARMLESS[0] }, { event: 'build', version: HARMLESS[1] }];

const NAMES = ['token', 'password', 'signature', 'nationalId', 'phone', 'subscriberName', 'address'];
const FORMAT = (d) => typeof d === 'string' && /^[A-Za-z0-9]{20,}$/.test(d);

function mask(value, { deep, format }, level = 0) {
  if (Array.isArray(value)) return deep ? value.map((x) => mask(x, { deep, format }, level + 1)) : value;
  if (value && typeof value === 'object') {
    if (!deep && level > 0) return value;
    return Object.fromEntries(Object.entries(value).map(([k, v]) =>
      [k, NAMES.includes(k) ? '***' : mask(v, { deep, format }, level + 1)]));
  }
  return format && FORMAT(value) ? '***' : value;
}

const write = (g, ...s) => console.log(s.map((v, i) =>
  (g[i] < 0 ? String(v).padEnd(-g[i]) : String(v).padStart(g[i]))).join(''));
const ITEMS = records.reduce((a, [, d]) => a + d.length, 0);
const D = [-34, 8, 10, 12, 16];
write(D, 'layer', 'items', 'closed', 'uncovered', 'false positive');

const result = {};
for (const [name, settings] of [
  ['no layer', null],
  ['name list, top level only', { deep: false, format: false }],
  ['name list, every level', { deep: true, format: false }],
  ['name list + format', { deep: true, format: true }],
]) {
  let remaining = 0;
  const remainingByType = {};
  for (const [record, sensitive, type] of records) {
    const text = JSON.stringify(settings ? mask(record, settings) : record);
    const k = sensitive.filter((d) => text.includes(d)).length;
    remaining += k;
    if (k) remainingByType[type] = (remainingByType[type] ?? 0) + k;
  }
  const alarm = settings ? harmlessRecords.filter((k) =>
    !JSON.stringify(mask(k, settings)).includes(HARMLESS[harmlessRecords.indexOf(k)])).length : 0;
  result[name] = remainingByType;
  write(D, name, ITEMS, ITEMS - remaining, remaining, alarm);
}

console.log('\ntype of uncovered items:');
for (const [name, type] of Object.entries(result)) {
  if (name === 'no layer') continue;
  console.log(`  ${name.padEnd(30)}${Object.entries(type).map(([t, n]) => `${t} ${n}`).join(', ') || '-'}`);
}

layer                                items    closed   uncovered  false positive
no layer                                11         0          11               0
name list, top level only               11         3           8               0
name list, every level                  11         8           3               0
name list + format                      11         9           2               2

type of uncovered items:
  name list, top level only     nested field 2, free text 1, query string 1, array item 2, name not in list 1, third level 1
  name list, every level        free text 1, query string 1, name not in list 1
  name list + format            free text 1, query string 1

The Value With No Name

Eight log records hold eleven sensitive items, and these come from two separate classes: part of them are secret-natured values — token, password, signature — and part of them are personal data. The two classes have different reasons for closure. A secret leak hands over an authority and closes with rotation; a personal-data leak does not hand over anything transferable but cannot be undone, because there is no rotating counterpart for it. The same masking layer covers both at once, so the item count can be done without separating them; but which class the uncovered item belongs to is what decides prioritization.

The second row is most setups’ starting point — there is a name list and it only looks at top-level fields. It closes three of the eleven items, eight stay uncovered. The types of those left uncovered are in the table below: nested field two, array item two, third level one, free text one, query string one, name not in list one.

The third row shows how much a single change buys: when the same name list also runs at every level and inside arrays, the closed-item count rises from three to eight. It is a structural fix, requires no new rule, and on its own gains more than half of the coverage. Three items remain, and all three remain for the same reason: the place where the value sits has no field name.

The fourth row adds format-based masking — values longer than twenty characters made up only of letters and digits get masked. The closed-item count rises to nine; the one item gained is the “name not in list” row, because even though the value’s name is not known, its format is recognized. The cost is written on the same row: two false positives. The tracing id and the build version stamp also fit the same format and get masked, and these are exactly the fields read for troubleshooting. Here, masking buys a diagnostic loss in exchange for a security gain.

The last two items do not close under any arrangement. One is a password embedded inside a free-text error message, the other is a token in a link’s query portion. Neither has a field name; one is part of a sentence, the other part of a string. A masking layer can only find these by parsing the string’s content, and at that point it is no longer a masking layer but a text scan — a defense whose coverage is uncertain and whose false-alarm rate is unmeasured.

When a New Point Is Added

The third column gives two separate answers across the two measurements. On the error-response side, the pattern covers on its own: once local response writing is disabled, a ninth endpoint added tomorrow also has to pass through the central handler, and this requires no decision. Coverage is complete regardless of the endpoint count.

On the log side, the pattern does not cover on its own. A name list running at every level covers a new record, but does not cover a new field name: a sensitive field written to the log tomorrow keeps showing up if its name is not in the list. In this lesson’s measure, the counterpart to that is the “name not in list” row, and format-based masking only catches it if the format is recognized. This is where the two defenses differ: one closes a path, the other updates a list. The path-closing defense covers the new point on its own; the list-updating defense waits to be remembered once more at every new point.

Summary

• Each of the eight endpoints carries five internal-information items; when the error object is written straight into the response, the item-response pairs leaking out come to 40.
• The central error handler covers six endpoints, the two endpoints that write their own response stay uncovered and ten pairs remain standing; once local response writing is disabled, the count drops to zero.
• Eight log records hold eleven sensitive items; a name list that only looks at the top level closes three, the same list running at every level and inside arrays closes eight.
• Format-based masking raises coverage to nine and produces two false positives; the two values it masks are the tracing id and the version stamp read for troubleshooting.
• The value embedded in free text and the value in the link’s query string close under no arrangement, because neither has a field name.
• A new endpoint is covered on its own once the central handler is mandatory; a new log field is not covered until the name list is updated.

Next Step

This lesson counted the points where the process talks outward, and in every one of them what was measured was the behavior of the code we wrote ourselves: which line puts the stack trace into the response, which field gets masked. Yet most of the code that serves a request is not lines the team wrote. The same process loads dozens of components, each one pulls in other components, and none of their names appear anywhere we wrote. The next lesson treats this set as a graph: how deep the dependency chain runs, how many packages a single component affects, and why a flaw in a component that is never called is prioritized differently.