revise July 2020 logging articles
Build and deploy / deploy (push) Successful in 13s

This commit is contained in:
2026-07-31 11:36:52 +03:00
parent 6c4f980f51
commit 8ae2b93876
7 changed files with 740 additions and 1 deletions
+470
View File
@@ -0,0 +1,470 @@
import { resolve } from 'node:path';
import { fileURLToPath } from 'node:url';
function escapeHtml(value) {
return String(value)
.replaceAll('&', '&')
.replaceAll('<', '&lt;')
.replaceAll('>', '&gt;')
.replaceAll('"', '&quot;')
.replaceAll("'", '&#039;');
}
function paragraph(text) {
return '<p>' + text + '</p>';
}
function heading(text) {
return '<h2>' + text + '</h2>';
}
function codeBlock(lines) {
return '<pre><code>' + escapeHtml(lines.join('\n')) + '</code></pre>';
}
function figure(src, alt, caption) {
return '<figure><img src="' + src + '" alt="' + alt + '" loading="lazy" /><figcaption>' + caption + '</figcaption></figure>';
}
function orderedList(items) {
return '<ol>' + items.map((item) => '<li>' + item + '</li>').join('') + '</ol>';
}
function dataTable(caption, headers, rows) {
const head = '<thead><tr>' + headers.map((header) => '<th scope="col">' + header + '</th>').join('') + '</tr></thead>';
const body = '<tbody>' + rows.map((row) => '<tr>' + row.map((cell) => '<td>' + cell + '</td>').join('') + '</tr>').join('') + '</tbody>';
return '<div class="table-scroll"><table><caption>' + escapeHtml(caption) + '</caption>' + head + body + '</table></div>';
}
function sourceList(items) {
return '<ul>' + items.map((item) => '<li><a href="' + item.url + '" target="_blank" rel="noopener noreferrer">' + item.title + '</a> — ' + item.note + '</li>').join('') + '</ul>';
}
function visibleText(html) {
return html
.replace(/<[^>]*>/g, ' ')
.replaceAll('&nbsp;', ' ')
.replaceAll('&quot;', '"')
.replaceAll('&#039;', "'")
.replaceAll('&lt;', '<')
.replaceAll('&gt;', '>')
.replaceAll('&amp;', '&')
.replace(/\s+/g, ' ')
.trim();
}
function proseText(html) {
return visibleText(
html
.replace(/<pre><code>[\s\S]*?<\/code><\/pre>/g, '')
.replace(/<figure>[\s\S]*?<\/figure>/g, '')
.replace(/<div class="table-scroll">[\s\S]*?<\/div>/g, ''),
);
}
function createRevision(meta, bodyParts, sources) {
const bodyHtml = bodyParts.join('\n');
const proseLength = proseText(bodyHtml).length;
if (proseLength < 5000 || proseLength > 15000) {
throw new Error(meta.slug + ': prose length must be 5000–15000, got ' + proseLength);
}
if (sources.length < 2) {
throw new Error(meta.slug + ': at least two primary or official sources are required');
}
return {
...meta,
contentHtml: [bodyHtml, heading('Проверяемые источники'), sourceList(sources)].join('\n'),
proseLength,
};
}
const rfc5424 = {
title: 'RFC 5424: The Syslog Protocol',
url: 'https://www.rfc-editor.org/rfc/rfc5424.html',
note: 'задаёт отдельные поля заголовка и формат STRUCTURED-DATA; это полезный контрпример строке, которую затем приходится разбирать регулярным выражением',
};
const rfc8259 = {
title: 'RFC 8259: The JavaScript Object Notation (JSON) Data Interchange Format',
url: 'https://www.rfc-editor.org/rfc/rfc8259.html',
note: 'фиксирует правила JSON-значений и строк; логгер должен выдавать валидную запись, а не склеивать псевдо-JSON вручную',
};
const pinoApi = {
title: 'Pino: API documentation',
url: 'https://github.com/pinojs/pino/blob/main/docs/api.md',
note: 'документирует дочерние логгеры и параметр redact; перед применением нужно сверить эти возможности с версией, установленной в конкретном проекте',
};
const owaspLogging = {
title: 'OWASP Logging Cheat Sheet',
url: 'https://cheatsheetseries.owasp.org/cheatsheets/Logging_Cheat_Sheet.html',
note: 'перечисляет данные, которые не следует писать в журнал, и предлагает проверять событие до записи',
};
const syntheticNotice = 'Все идентификаторы, маршруты и значения в примерах ниже учебные и синтетические. Это не журнал реального пользователя и не отчёт о production-инциденте.';
function redactContext(value, key = '') {
const sensitiveKeys = new Set(['authorization', 'cookie', 'password', 'token', 'secret']);
if (sensitiveKeys.has(key.toLowerCase())) return '[REDACTED]';
if (Array.isArray(value)) return value.map((item) => redactContext(item));
if (value && typeof value === 'object') {
return Object.fromEntries(Object.entries(value).map(([childKey, childValue]) => [
childKey,
redactContext(childValue, childKey),
]));
}
return value;
}
export function runStructuredLogFixture() {
const requiredFields = ['timestamp', 'level', 'service', 'environment', 'event', 'request_id', 'message'];
const event = {
timestamp: '2020-07-14T09:30:11.042Z',
level: 'info',
service: 'demo-catalog-api',
environment: 'training',
event: 'http.request.completed',
request_id: 'req-demo-20200714-01',
message: 'Synthetic request completed',
http: { method: 'POST', route: '/training/orders/:orderId', status_code: 202 },
};
const sanitized = redactContext({
request_id: 'req-demo-20200714-01',
headers: {
authorization: 'synthetic-placeholder-not-a-secret',
cookie: 'synthetic-cookie-placeholder',
},
order_state: 'accepted',
});
const missing = requiredFields.filter((field) => !(field in event));
if (missing.length > 0) throw new Error('fixture is missing required fields: ' + missing.join(', '));
if (sanitized.headers.authorization !== '[REDACTED]' || sanitized.headers.cookie !== '[REDACTED]') {
throw new Error('fixture did not redact synthetic sensitive fields');
}
if (!/^req-demo-[0-9]{8}-[0-9]{2}$/.test(event.request_id)) {
throw new Error('fixture request_id does not follow the documented training format');
}
return {
fixture: 'Deterministic training fixture; it does not send a request or read production logs.',
requiredFields,
requestId: event.request_id,
redactedAuthorization: sanitized.headers.authorization,
eventName: event.event,
};
}
const practiceArticle = createRevision(
{
slug: 'editorial-2020-07-practice-structured-logs',
title: 'Структурированные логи: сначала контракт одного события',
categories: ['Backend', 'Наблюдаемость', 'Практика'],
cover: '/assets/editorial/2020/structured-log-event-2020.svg',
excerpt: 'Связываем один учебный запрос по request_id, фиксируем обязательные поля события и не превращаем журнал в склад сырых объектов.',
readingMinutes: 13,
},
[
paragraph('Проблема проявляется не в момент записи лога, а через несколько часов: в журнале есть «ошибка оплаты», «запрос завершён» и стек, но нельзя понять, относятся ли они к одному действию. Человек вручную сопоставляет время, маршрут и случайный текст. Цена такого поиска — ложная причина, лишняя правка и риск оставить следующую ошибку без ответа. Строка удобна для глаз, пока журнал короткий; для проверки конкретного запроса она слишком неоднозначна.'),
paragraph('В июле 2020 я бы не начинал с большой платформы наблюдаемости. Достаточно договориться о контракте одного события и провести через приложение один <code>request_id</code>. Тогда у записи есть известные поля, у запроса — один ключ поиска, а у ревью — конкретный объект проверки. Цель этой практики скромнее полной распределённой трассировки: собрать последовательность событий одного учебного HTTP-запроса и не потерять смысл при сериализации.'),
heading('Событие — это контракт, а не оформленная строка'),
paragraph('Структурированный лог — JSON-объект с устойчивыми именами полей. Его сообщение остаётся коротким объяснением для человека, но поиск и группировка опираются не на порядок слов, а на <code>event</code>, уровень, сервис и идентификатор запроса. RFC 5424 разделяет заголовок и структурированные данные именно потому, что отдельные значения должны быть распознаваемыми. JSON не делает событие полезным автоматически: полезность появляется, когда поля имеют владельца и одинаковый смысл в каждом модуле.'),
paragraph('Я разделяю обязательные и локальные поля. Обязательные пишутся на каждом значимом событии HTTP-обработки: время, уровень, сервис, среда, имя события, идентификатор запроса и краткое сообщение. Локальные поля добавляет владелец операции: маршрут, код ответа, имя адаптера или длительность конкретного шага. Не стоит помещать в базовый объект целый <code>req</code>, ответ базы или объект пользователя. Такой объект плохо читается, имеет случайную форму и почти наверняка приносит данные, которые журналу не нужны.'),
dataTable(
'Минимальный контракт учебного события',
['Поле', 'Кто задаёт', 'Разрешённая форма', 'Какой вопрос закрывает'],
[
['<code>timestamp</code>', 'логгер', 'UTC ISO-8601', 'Когда зафиксировано событие?'],
['<code>level</code>', 'код операции', '<code>debug</code>, <code>info</code>, <code>warn</code>, <code>error</code>', 'Насколько срочно его смотреть?'],
['<code>service</code>', 'конфигурация процесса', 'устойчивое имя сервиса', 'Где оно произошло?'],
['<code>environment</code>', 'конфигурация процесса', 'например, <code>training</code>', 'Не смешаны ли учебные и другие записи?'],
['<code>event</code>', 'владелец операции', 'словарное имя <code>noun.verb</code>', 'Что именно изменилось?'],
['<code>request_id</code>', 'HTTP-граница', 'один валидированный идентификатор', 'Какие записи принадлежат одному запросу?'],
['<code>message</code>', 'владелец операции', 'короткая причина для чтения', 'Что произошло без разбора всех полей?'],
],
),
figure('/assets/editorial/2020/structured-log-event-2020.svg', 'Вертикальная схема учебного JSON-события: обязательные поля timestamp, level, service, environment, event, request_id и message отделены от локального блока http с методом, шаблоном маршрута и кодом статуса', 'Контракт держит общие поля наверху, а контекст операции — в отдельном вложенном блоке. Так парсер знает, где искать основу, а модуль не обязан притворяться владельцем чужих данных.'),
heading('Собираем запись до того, как она попадёт в stdout'),
paragraph('Первый шаг — сделать маленькую функцию, которая принимает только понятный контекст и возвращает объект. Это не универсальная обёртка вокруг всего приложения. Её задача — не дать коду случайно написать строку с другой формой или забыть <code>request_id</code>. В учебном примере время приходит параметром: так проверка не зависит от текущих часов. В реальном приложении время обычно добавляет логгер, но контракт от этого не меняется.'),
codeBlock([
'const required = [',
" 'timestamp', 'level', 'service', 'environment',",
" 'event', 'request_id', 'message'",
'];',
'',
'function buildTrainingEvent(base, local) {',
' const event = { ...base, ...local };',
' const missing = required.filter((name) => event[name] === undefined);',
" if (missing.length) throw new Error('missing log fields: ' + missing.join(', '));",
' return event;',
'}',
'',
'const entry = buildTrainingEvent(',
' {',
" timestamp: '2020-07-14T09:30:11.042Z',",
" level: 'info', service: 'demo-catalog-api', environment: 'training',",
" event: 'http.request.completed', request_id: 'req-demo-20200714-01',",
" message: 'Synthetic request completed'",
' },',
" { http: { method: 'POST', route: '/training/orders/:orderId', status_code: 202 } }",
');',
'process.stdout.write(JSON.stringify(entry) + "\\n");',
]),
paragraph('Здесь <code>route</code> — шаблон, а не полный URL с параметром. Это сразу ограничивает кардинальность: для ста заказов остаётся один маршрут, а не сто новых значений. <code>event</code> тоже выбирается из небольшого словаря, например <code>http.request.received</code>, <code>order.validation.failed</code>, <code>http.request.completed</code>. Если имя события собирается из текста ошибки или номера заказа, его нельзя надёжно считать и сравнивать.'),
paragraph('Не надо подменять контракт декоративной вложенностью. Поля <code>timestamp</code> и <code>request_id</code> нужны в одном и том же месте, потому что по ним читается любая запись. Вложенный <code>http</code> нужен только HTTP-событиям. У воркера вместо него может быть <code>job</code>; у интеграции — <code>adapter</code>. Общий корень остаётся одним, но контекст не превращается в плоский список из пятидесяти пустых полей.'),
heading('Проверяем один синтетический запрос целиком'),
paragraph(syntheticNotice),
codeBlock([
'{"timestamp":"2020-07-14T09:30:11.001Z","level":"info","service":"demo-gateway","environment":"training","event":"http.request.received","request_id":"req-demo-20200714-01","message":"Synthetic request accepted","http":{"method":"POST","route":"/training/orders/:orderId"}}',
'{"timestamp":"2020-07-14T09:30:11.021Z","level":"info","service":"demo-catalog-api","environment":"training","event":"order.validation.completed","request_id":"req-demo-20200714-01","message":"Synthetic order passed validation","order":{"state":"accepted"}}',
'{"timestamp":"2020-07-14T09:30:11.042Z","level":"info","service":"demo-gateway","environment":"training","event":"http.request.completed","request_id":"req-demo-20200714-01","message":"Synthetic request completed","http":{"status_code":202,"duration_ms":41}}',
'',
"# Учебный поиск по одному запросу, файл training.jsonl не является production-журналом:",
"jq -c 'select(.request_id == \"req-demo-20200714-01\")' training.jsonl",
]),
paragraph('Проверка отвечает на узкий вопрос: есть ли три ожидаемые записи с одинаковым <code>request_id</code> и различными владельцами? Она не доказывает, что запрос прошёл все возможные сервисы, и не заменяет трассу критического пути. Если второй сервис не пишет запись, диагноз звучит конкретно: контекст не был передан через эту границу или событие не было добавлено. Это лучше, чем искать по минуте и надеяться, что порядок строк совпал.'),
heading('Неизбежные ограничения контракта'),
paragraph('Поле <code>request_id</code> высококардинально: почти каждый запрос даёт новое значение. Это нормально для поиска конкретной истории, но плохая причина использовать его как измерение в агрегате или как часть имени события. Похожая ошибка — писать <code>user_id</code>, адрес почты, полный query string или текст входного тела «на всякий случай». Они не помогают базовой проверке одного запроса и расширяют поверхность приватных данных. В минимальном контракте их нет.'),
paragraph('Чувствительные ключи нужно редактировать до сериализации и тестировать отдельно. Маска в интерфейсе просмотра недостаточна: строка уже могла попасть в файл, транспорт или резервную копию. В этой партии учебный fixture заменяет <code>authorization</code> и <code>cookie</code> на <code>[REDACTED]</code>; он не использует реальные токены. Список путей redaction зависит от формы объекта, поэтому его надо держать рядом с кодом, который формирует запись, а не надеяться на память автора запроса.'),
dataTable(
'Политика для значений, которые часто попадают в журнал случайно',
['Значение', 'Почему опасно', 'Действие в минимальном контракте'],
[
['Полный объект HTTP-запроса', 'форма меняется и может содержать заголовки или тело', 'не передавать в логгер; выбрать 2–3 нужных поля'],
['<code>authorization</code>, <code>cookie</code>, <code>password</code>', 'секрет или материал для повторного доступа', 'redaction или полное исключение до JSON'],
['Полный URL с параметрами', 'создаёт много уникальных строк и может нести личные данные', 'писать шаблон маршрута'],
['Текст ошибки от внешней стороны', 'может быть длинным и нестабильным', 'писать нормализованную причину и технический код'],
],
),
heading('Проверяем контракт как часть изменения, а не после поиска'),
paragraph('Контракт ломается тихо: новый обработчик пишет <code>requestId</code> вместо <code>request_id</code>, забывает <code>environment</code> или собирает <code>event</code> из текста исключения. JSON при этом остаётся валидным, поэтому парсер не жалуется. Нужна более предметная проверка. Для каждого учебного события тест строит объект, сверяет обязательные ключи, проверяет формат идентификатора и сравнивает имя события с разрешённым словарём. Это не заменяет типы и не требует отдельного сервиса схем, но ловит расхождение до того, как оно станет привычкой в соседних модулях.'),
paragraph('Полезно разделить проверку записи и проверку маршрута. Запись проверяет форму одного JSON-объекта: поля существуют, значения не пустые, чувствительный ключ замаскирован. Маршрут проверяет связь: три синтетические записи имеют один <code>request_id</code>, среди них есть начало и завершение, а локальная операция принадлежит ожидаемому сервису. Если тест падает на форме, исправляют builder. Если на связи, смотрят место передачи контекста. Одно красное сообщение не смешивает две причины, поэтому действие остаётся коротким.'),
paragraph('Словарь событий тоже стоит ревьюить как API. Имя <code>http.request.completed</code> говорит о факте, а не о конкретной реализации; <code>postgres.timeout.42</code> смешивает компонент, причину и случайный номер. Когда событие приходится переименовать, старое значение не нужно оставлять «на всякий случай» во всех ветках. Лучше явно обозначить переход и обновить учебный запрос. Иначе поиск начнёт возвращать два почти одинаковых набора, а следующая статья снова будет объяснять, почему журнал нельзя читать автоматически.'),
heading('Граница с числовыми сигналами'),
paragraph('Лог отвечает на вопрос о конкретном случае: что происходило с <code>req-demo-20200714-01</code>? Числовой сигнал отвечает на другой вопрос: как часто повторяется известный вид события? В этом месяце достаточно не смешивать эти роли. Уникальный request_id полезен в JSONL, но не должен становиться ключом для подсчёта. Напротив, ограниченное <code>event</code> и <code>service</code> можно позднее использовать для простого числа случаев. Такое разделение предотвращает два симметричных дефекта: попытку искать один запрос в агрегате и попытку хранить бесконечный набор уникальных значений ради красивого графика.'),
paragraph('Из этого следует практическое правило для автора события. Сначала он спрашивает: «мне нужно найти одну историю или сравнить повторяющиеся случаи?» В первом ответе добавляет request_id и локальный контекст. Во втором выбирает небольшой словарь имён и нормализованный код. Если требуется оба ответа, поля существуют рядом, но их назначение не смешивается. Никакой готовой платформы здесь не предполагается: договорённость уже работает в одном файле JSONL и не мешает более зрелому инструменту появиться позже.'),
heading('Маршрут внедрения без большой переделки'),
orderedList([
'Выбрать один HTTP-маршрут для учебной проверки и выписать его владельцев.',
'Зафиксировать семь обязательных полей и словарь из трёх–пяти имён событий.',
'Добавить <code>request_id</code> на входной границе и передать дочерний логгер в следующий модуль.',
'Сгенерировать только синтетический запрос и проверить поиск всех его записей по одному идентификатору.',
'Добавить redaction для известных чувствительных ключей, затем проверить, что fixture не выпускает их значение.',
'Только после этого повторить схему на соседнем маршруте; не переносить сырые объекты ради скорости внедрения.',
]),
paragraph('Результат этой работы не «наблюдаемость вообще». Он проще и полезнее: при следующей ошибке у команды есть единый формат, один ключ поиска и граница между диагностикой и лишними данными. Если вопрос уже требует увидеть параллельные вызовы, критический путь или историю между независимыми процессами, это отдельная следующая задача. Нельзя достраивать её задним числом из строки, в которой не договорились даже о владельце события.'),
],
[rfc5424, rfc8259, pinoApi, owaspLogging],
);
const mechanismArticle = createRevision(
{
slug: 'editorial-2020-07-mechanism-structured-logs',
title: 'Один request_id через границы: как связать журнал без ложной трассировки',
categories: ['Backend', 'Delivery', 'Диагностика'],
cover: '/assets/editorial/2020/structured-log-correlation-2020.svg',
excerpt: 'Определяем владельца request_id на HTTP-границе, передаём его через дочерний логгер и честно отделяем корреляцию одного запроса от распределённой трассировки.',
readingMinutes: 14,
},
[
paragraph('Симптом выглядит как три независимые ошибки: gateway вернул 502, API пишет о невалидном ответе адаптера, а worker сообщает о повторе операции. Время у строк близкое, но этого недостаточно: соседний запрос мог попасть в тот же промежуток. Цена угадывания — обвинить последний сервис в журнале, изменить таймаут и скрыть настоящую границу, где пропал контекст. Нужна не ещё одна строка, а способ доказать принадлежность записей одному запросу.'),
paragraph('Для этого в июле 2020 достаточно внутреннего <code>request_id</code>. Он создаётся или принимается на входной HTTP-границе, проверяется по простому формату и затем передаётся дальше вместе с логгером. Это корреляция одного запроса, не полноценная распределённая трассировка. Она не строит спаны, не вычисляет критический путь и не обещает объяснить параллельную работу. Зато она отвечает на проверяемый вопрос: какие известные события принадлежат этому синтетическому действию?'),
heading('Сначала назначаем владельца идентификатора'),
paragraph('Идентификатор нельзя генерировать в каждом модуле. Если gateway, контроллер и адаптер создадут по своему значению, журнал снова распадётся на части, хотя каждое сообщение формально структурировано. Владельцем становится первая граница, которая приняла запрос. Для HTTP это middleware или обработчик до роутинга. Он берёт входной <code>X-Request-Id</code> только если значение похоже на ожидаемый служебный формат; иначе создаёт новое и добавляет его в ответ для ручной проверки.'),
paragraph('Проверка входного значения нужна по двум причинам. Первая — не позволить клиенту записать в поле тысячу символов или управляющие знаки. Вторая — сохранить предсказуемый поиск: если поле принимает всё, оно становится текстом, а не ключом. Это не криптографическая гарантия и не идентификатор пользователя. В учебном пакете формат нарочно читаемый: <code>req-demo-YYYYMMDD-NN</code>. В рабочем коде выбирается формат проекта, но правило остаётся тем же — один владелец, один валидатор, одно значение на маршрут.'),
dataTable(
'Граница и судьба request_id',
['Момент', 'Кто владеет полем', 'Проверка', 'Что запрещено'],
[
['Вход HTTP', 'middleware gateway', 'длина и допустимые символы входного заголовка', 'молча копировать произвольный текст клиента'],
['Вызов API', 'вызывающий модуль', 'передаёт то же значение в заголовке и дочернем логгере', 'генерировать второй id «для удобства»'],
['Локальная операция', 'владелец операции', 'добавляет <code>component</code> или <code>event</code>', 'заменять request_id номером заказа'],
['Ответ клиенту', 'gateway', 'отражает валидный request_id', 'считать это доказательством полной трассировки'],
],
),
figure('/assets/editorial/2020/structured-log-correlation-2020.svg', 'Вертикальная схема одного учебного запроса: gateway создаёт request_id, передаёт его в HTTP-заголовке и дочернем логгере сервису catalog-api; оба сервиса пишут события с тем же ключом, после чего учебный запрос к JSONL выбирает три записи', 'Корреляция проходит по явному контракту: один ключ приходит на вход, передаётся через границу и повторяется в событиях. Стрелки не изображают spans или измеренный critical path.'),
heading('Передаём контекст как зависимость, а не через глобальную переменную'),
paragraph('Плохой путь — положить текущий идентификатор в модульную переменную. Два одновременных запроса перезапишут её, и строки начнут менять владельца. Второй плохой путь — прокидывать только строку и надеяться, что каждый разработчик не забудет добавить её в лог. Практичнее создать дочерний логгер или небольшой контекстный объект у входа и передавать его явно в функцию, которая делает следующий вызов. Тогда место передачи видно в сигнатуре и в code review.'),
codeBlock([
'function isRequestId(value) {',
" return typeof value === 'string' && /^req-demo-[0-9]{8}-[0-9]{2}$/.test(value);",
'}',
'',
'function requestContext(baseLogger) {',
' return function middleware(req, res, next) {',
" const incoming = req.get('x-request-id');",
" const requestId = isRequestId(incoming) ? incoming : 'req-demo-20200714-01';",
' req.log = baseLogger.child({',
' request_id: requestId,',
" service: 'demo-gateway',",
" environment: 'training'",
' });',
" res.setHeader('x-request-id', requestId);",
' next();',
' };',
'}',
'',
'async function submitTrainingOrder(context, client) {',
" context.log.info({ event: 'order.submit.started' }, 'Synthetic order submission started');",
" await client.post('/training/orders', { headers: { 'x-request-id': context.request_id } });",
'}',
]),
paragraph('В этом фрагменте строка <code>request_id</code> живёт и в дочернем логгере, и в контексте вызова. Первый нужен, чтобы каждая запись автоматически получила общий ключ. Второй нужен клиенту, который передаёт заголовок через HTTP-границу. Код учебный: генератор возвращает фиксированное значение, чтобы пример был воспроизводим. Он не моделирует конкуренцию, реальный сервер или сохранение контекста между процессами.'),
paragraph('У вложенных операций может появиться собственный <code>operation_id</code>, но он не заменяет <code>request_id</code>. Например, один запрос запускает несколько независимых попыток записи. Тогда request_id отвечает на вопрос «к какому входному действию относится строка?», а operation_id — «какая локальная попытка её создала?». Если в статье нет этого различия, повтор задачи легко ошибочно принять за второй пользовательский запрос. Начинать всё равно лучше с первого ключа; второй добавляют только при реальном вопросе диагностики.'),
heading('Показываем путь одного синтетического запроса'),
paragraph(syntheticNotice),
codeBlock([
'{"timestamp":"2020-07-14T09:30:11.001Z","service":"demo-gateway","level":"info","event":"http.request.received","request_id":"req-demo-20200714-01","message":"Synthetic request accepted"}',
'{"timestamp":"2020-07-14T09:30:11.018Z","service":"demo-catalog-api","level":"info","event":"catalog.reserve.started","request_id":"req-demo-20200714-01","message":"Synthetic reservation started"}',
'{"timestamp":"2020-07-14T09:30:11.042Z","service":"demo-gateway","level":"info","event":"http.request.completed","request_id":"req-demo-20200714-01","message":"Synthetic request completed"}',
'',
"# Учебный запрос: выбираем только события одного request_id, затем сортируем по времени.",
"jq -s 'map(select(.request_id == \"req-demo-20200714-01\")) | sort_by(.timestamp)' training.jsonl",
]),
paragraph('У ожидаемого результата три записи: вход, локальная операция и завершение. Если API-строка содержит другой идентификатор, причиной может быть новая генерация на исходящем вызове. Если её нет совсем, контекст мог не дойти до клиента или событие отсутствует. Если есть две одинаковые строки завершения, проверяем, не выполнен ли обработчик дважды. В каждом случае следующий шаг привязан к границе кода, а не к расплывчатому «посмотреть логи внимательнее».'),
heading('Корреляция не равна причинности'),
paragraph('Одинаковый request_id говорит о принадлежности одному входному действию, но не доказывает порядок работы на уровне процессора или сети. Часы разных машин могут расходиться; асинхронный вызов может дописать событие позже; две ветви могут идти параллельно. Поэтому в минимальном журнале время используется как ориентир, а не как абсолютная схема зависимости. Если нужно найти критический путь, измерить ожидание между сервисами или собирать дочерние операции, это уже задача отдельного трассировочного контракта.'),
paragraph('Такое ограничение защищает текст от ложной уверенности. Можно честно показать один путь в JSONL, не рисуя систему так, будто она уже знает все связи. Внутренний заголовок тоже не делает интеграцию безопасной сам по себе: он должен быть ограничен форматом, не должен нести пользователя или секрет и не должен попадать в бизнес-ключ. Отражать его клиенту удобно для ручной проверки, но это не разрешение принимать произвольный внешний идентификатор без проверки.'),
dataTable(
'Вопрос диагностики и достаточный уровень контекста',
['Вопрос', 'Достаточно request_id?', 'Что ещё нужно', 'Не делать преждевременно'],
[
['Какие записи относятся к одному HTTP-действию?', 'да', 'одинаковое поле во всех локальных событиях', 'искать по приблизительному времени'],
['Где пропал контекст между двумя сервисами?', 'да', 'лог на обеих сторонах HTTP-границы', 'вводить платформу ради одной проверки'],
['Какая ветвь определила критический путь?', 'нет', 'отдельная модель дочерних операций и времени', 'делать вывод по сортировке строк'],
['Почему задача выполнилась повторно?', 'частично', 'operation_id и состояние попытки', 'считать каждый лог новым запросом'],
],
),
heading('Три места, где контекст теряется чаще всего'),
paragraph('Первое место — исходящий HTTP-клиент. В контроллере есть дочерний логгер, но вызов клиента создаётся глубоко в адаптере и не получает заголовок. Симптом: на стороне gateway событие есть, на стороне API его нельзя найти по тому же ключу. Причина не в поисковом запросе, а в скрытой зависимости. Проверка проста: учебный клиент должен принимать контекст или request_id явно и записывать его в синтетический заголовок. Действие — передать этот объект в сигнатуру адаптера, а не получать «текущий запрос» из глобального состояния.'),
paragraph('Второе место — обработчик ошибки. Код ловит исключение, создаёт новый логгер без базового контекста и пишет красивую <code>error</code>-строку. Симптом: именно самое важное событие оказывается без request_id. Причина — обработчик видит ошибку как отдельную операцию, хотя он всё ещё внутри исходного запроса. Проверка — добавить в учебный путь контролируемую ошибку и убедиться, что <code>error.code</code>, service и тот же ключ остаются на месте. Действие — передавать дочерний логгер в ветку catch и нормализовать причину вместо сериализации всего исключения.'),
paragraph('Третье место — отложенная задача. Она может быть действительно новым действием, а не продолжением HTTP-запроса. Тогда нельзя механически копировать request_id и выдавать запись за непрерывную трассу. На входе в очередь лучше сохранить явную ссылку на инициирующий запрос только если это необходимо для расследования, а у самой попытки завести отдельный operation_id. В этом пакете такая очередь не реализована: ограничение намеренно зафиксировано, чтобы пример одного синтетического HTTP-запроса не создавал ложного правила для фоновой работы.'),
paragraph('Эти три случая показывают, почему корреляция — контракт границ, а не свойство библиотеки. Логгер может облегчить дочерний контекст, но не может сам угадать, куда код отправит HTTP-вызов, где обработает ошибку и что считается новой операцией. Пока каждая из этих границ названа, review видит место решения. Когда она скрыта, даже хороший JSON распадается на отдельные аккуратные, но бесполезные события.'),
heading('Маршрут проверки перед расширением схемы'),
orderedList([
'Выбрать одну входную границу и объявить её владельцем request_id.',
'Описать валидный формат и явное поведение для отсутствующего либо невалидного заголовка.',
'Создать дочерний логгер на границе и передавать контекст явно через исходящий клиент.',
'Сделать три синтетические записи от двух модулей с одним идентификатором.',
'Выполнить учебный JSONL-запрос и проверить, что потеря либо замена ключа заметна.',
'Отдельно решить, нужен ли operation_id; не добавлять trace-термины, если нет модели spans и их проверки.',
]),
paragraph('После такого прохода журнал становится пригоден для малого расследования: он показывает, где запрос вошёл, какой модуль сделал известный шаг и где завершился ответ. Это уже связывает backend и delivery, потому что граница HTTP видна с обеих сторон. Но результат остаётся ограниченным: ни production-метрик, ни SLO, ни полной распределённой трассировки здесь нет. Следующий шаг появляется только когда команда может сформулировать вопрос, на который одного request_id уже недостаточно.'),
],
[rfc5424, rfc8259, pinoApi, owaspLogging],
);
const fieldArticle = createRevision(
{
slug: 'editorial-2020-07-field-structured-logs',
title: 'Разбор журнала: redaction и кардинальность до первой аварии',
categories: ['Backend', 'Безопасность', 'Разбор'],
cover: '/assets/editorial/2020/structured-log-diagnosis-2020.svg',
excerpt: 'Выбираем поля для диагностики, удаляем чувствительные значения до сериализации и не превращаем event или route в бесконечный словарь.',
readingMinutes: 14,
},
[
paragraph('Проблема заметна поздно: нужное событие найдено, но рядом лежит целый объект запроса, длинный URL и строка, похожая на credential. Другой поиск не работает, потому что имя события каждый раз включает номер заказа или текст внешней ошибки. Цена — не только неудобная диагностика. Журнал становится местом, куда утекают лишние данные, а одинаковые случаи невозможно посчитать или сравнить без ручной очистки.'),
paragraph('Лечить это после первого серьёзного сбоя дорого: код уже привык писать «всё, что есть под рукой», а доступ к журналу обычно шире доступа к исходному запросу. Поэтому правила redaction и кардинальности нужны в точке формирования события. В этой статье нет настоящих инцидентов, секретов или production-логов: только синтетическая запись и локальный fixture. Задача — научиться отличать поле, нужное для ответа, от поля, которое журналу не принадлежит.'),
heading('Разделяем данные на три класса до вызова логгера'),
paragraph('Первый класс — безопасный операционный контекст. Это время, уровень, сервис, имя события, шаблон маршрута, код ответа и request_id. Они помогают связать одну историю и не требуют выгружать тело запроса. Второй класс — ограниченный контекст: технический код внешней ошибки, нормализованное состояние, короткое имя адаптера. Его добавляют, если есть точный вопрос диагностики и форма значения известна. Третий класс — запрещённый или redacted: учётные данные, cookies, заголовок authorization, пароль, полный body и произвольный объект пользователя.'),
paragraph('Разделение не означает, что второй класс всегда безопасен. Даже поле <code>error.message</code> может включить в себя входные данные внешней системы. Поэтому практический контракт предпочитает <code>error.code</code> и собственное имя события, а текст оставляет коротким и контролируемым. Если подробность действительно нужна, её нельзя добавлять в общий JSON по умолчанию: сначала определяется доступ, срок хранения и отдельный путь проверки. В этой минимальной схеме подробность отсутствует, а не прячется в красивом имени поля.'),
dataTable(
'Политика полей для учебного JSON-события',
['Класс', 'Примеры', 'Зачем они нужны', 'Действие перед записью'],
[
['Базовый', '<code>timestamp</code>, <code>service</code>, <code>event</code>, <code>request_id</code>', 'связать и прочитать один запрос', 'писать в устойчивом формате'],
['Ограниченный', '<code>adapter.name</code>, <code>error.code</code>, <code>http.status_code</code>', 'отделить известную ветвь отказа', 'добавлять только владельцем операции'],
['Redact', '<code>authorization</code>, <code>cookie</code>, <code>password</code>, <code>token</code>', 'не нужны для поиска события', 'заменить до JSON или не передавать объект'],
['Не логировать', 'body, полный URL, целый объект пользователя', 'случайная форма и лишние данные', 'заменить на шаблон маршрута или нормализованный код'],
],
),
figure('/assets/editorial/2020/structured-log-diagnosis-2020.svg', 'Вертикальное дерево решения для учебного поля: сначала проверяется диагностический вопрос, затем выбирается безопасное обязательное поле, ограниченный нормализованный контекст, redaction чувствительного значения или полный отказ от записи; внизу показан поиск одного синтетического request_id', 'Поле проходит через вопрос «зачем оно нужно?». Если ответ не приводит к проверяемому действию, значение не попадает в событие. Redaction — защита для известных путей, а не разрешение логировать весь объект.'),
heading('Redaction должен работать с объектом, а не с готовой строкой'),
paragraph('Ошибка redaction часто начинается с позднего шага: код уже сделал <code>JSON.stringify(req)</code>, затем регулярное выражение пытается вычеркнуть секрет из текста. Вложенный ключ, другой регистр или неожиданная форма легко проходят мимо такой маски. Надёжнее принять маленький объект контекста, пройти его по известным ключам и только потом сериализовать. Документация Pino описывает redaction путями полей; это тот же принцип: правило должно знать структуру, а не угадывать фрагмент строки.'),
codeBlock([
"const sensitiveKeys = new Set(['authorization', 'cookie', 'password', 'token', 'secret']);",
'',
'function redact(value, key = \'\') {',
" if (sensitiveKeys.has(key.toLowerCase())) return '[REDACTED]';",
' if (Array.isArray(value)) return value.map((item) => redact(item));',
' if (value && typeof value === \'object\') {',
' return Object.fromEntries(Object.entries(value).map(([name, item]) => [name, redact(item, name)]));',
' }',
' return value;',
'}',
'',
'const trainingContext = {',
" request_id: 'req-demo-20200714-01',",
" event: 'http.request.completed',",
" headers: { authorization: 'synthetic-placeholder-not-a-secret' },",
" http: { route: '/training/orders/:orderId', status_code: 202 }",
'};',
'process.stdout.write(JSON.stringify(redact(trainingContext)) + "\\n");',
'// authorization is emitted as [REDACTED]; no real credential is present in this fixture.',
]),
paragraph('Этот пример не обещает поймать каждый секрет во всех структурах. Он фиксирует минимум: известные чувствительные ключи не должны дойти до stdout в исходном виде. В реальном проекте список расширяется по фактическим форматам интеграций, а тесты добавляют каждый уже известный путь. Если библиотека поддерживает redaction конфигурацией, правило всё равно следует проверять на том JSON, который действительно выходит из процесса. Название опции — не доказательство результата.'),
paragraph('Есть и более простая защита: не давать логгеру сырой объект. Контроллер сам выбирает <code>method</code>, <code>route</code> и <code>status_code</code>; адаптер сам выбирает <code>adapter.name</code> и <code>error.code</code>. Тогда redaction остаётся страховочной сеткой, а не единственным барьером. Чем меньше произвольных объектов пересекает границу логирования, тем легче редактору и ревьюеру увидеть, откуда появилось поле.'),
heading('Кардинальность — это форма будущего поиска'),
paragraph('Кардинальность показывает, сколько разных значений может иметь поле. У <code>event</code> она должна быть низкой: десятки устойчивых имён, а не одна новая строка на исключение. У <code>route</code> тоже низкая: шаблон <code>/training/orders/:orderId</code>, а не конкретный путь. У <code>request_id</code> она намеренно высокая, потому что его задача — найти одну историю. Ошибка начинается, когда все эти поля используют одинаково — например, группируют по request_id или добавляют номер заказа в имя события.'),
paragraph('Не надо превращать эту заметку в рассказ о зрелой платформе метрик. Здесь достаточно заранее записать, какие поля допускаются как фильтр одного случая, а какие могут быть группой для короткого локального отчёта. Даже если команда пока читает JSONL через <code>jq</code>, это решение уже меняет качество диагностики: следующий разработчик не создаст сто вариантов события ради удобства одного сообщения.'),
dataTable(
'Кардинальность и назначение поля',
['Поле', 'Ожидаемая кардинальность', 'Разрешённое использование', 'Антипаттерн'],
[
['<code>event</code>', 'низкая', 'фильтр и небольшая группа', '<code>order.7421.failed</code>'],
['<code>service</code>', 'низкая', 'граница владельца', 'имя с номером pod или локальным путём'],
['<code>route</code>', 'низкая', 'сравнить обработчики', 'полный URL с id и query string'],
['<code>request_id</code>', 'высокая', 'найти одну историю', 'использовать как измерение агрегата'],
['<code>error.code</code>', 'ограниченная', 'разделить известные причины', 'писать произвольный текст исключения'],
],
),
heading('Разбираем один синтетический сбой без имитации инцидента'),
paragraph(syntheticNotice),
codeBlock([
'{"timestamp":"2020-07-14T09:30:11.001Z","level":"info","service":"demo-gateway","environment":"training","event":"http.request.received","request_id":"req-demo-20200714-01","message":"Synthetic request accepted","http":{"route":"/training/orders/:orderId"}}',
'{"timestamp":"2020-07-14T09:30:11.024Z","level":"warn","service":"demo-catalog-api","environment":"training","event":"adapter.response.rejected","request_id":"req-demo-20200714-01","message":"Synthetic adapter response rejected","adapter":{"name":"training-inventory","error_code":"TRAINING_SCHEMA_MISMATCH"}}',
'{"timestamp":"2020-07-14T09:30:11.042Z","level":"info","service":"demo-gateway","environment":"training","event":"http.request.completed","request_id":"req-demo-20200714-01","message":"Synthetic request completed","http":{"status_code":502}}',
'',
"# Учебная проверка: поле request_id связывает записи; error_code называет нормализованную причину.",
"jq -c 'select(.request_id == \"req-demo-20200714-01\")' training.jsonl",
]),
paragraph('Диагноз здесь не «адаптер плохой». Проверяемая цепочка короче: gateway принял учебный запрос, API записал нормализованный <code>TRAINING_SCHEMA_MISMATCH</code>, gateway завершил его 502. Если нужен следующий шаг, он относится к контракту учебного адаптера, а не к поиску несуществующего токена в журнале. Если в ответе появляется полное тело внешней системы, это новый дефект контракта логирования, а не удобный контекст.'),
heading('Проверяем redaction на форме, которая реально уходит в stdout'),
paragraph('Маска полезна только там, где объект окончательно превращается в JSON. Поэтому fixture должен проверять не внутренний JavaScript-объект, а результат сериализации: в нём есть обязательные безопасные поля, а вместо учебного placeholder в <code>headers.authorization</code> стоит ровно <code>[REDACTED]</code>. Такая проверка ловит порядок операций. Если разработчик случайно записал исходный контекст раньше, чем вызвал redaction, тест видит запрещённое значение в строке и не даёт считать код защищённым только по названию функции.'),
paragraph('У redaction есть предел. Он не исправит поле, которое автор назвал <code>access</code> вместо <code>token</code>, и не решит, что делать с вложенной строкой, куда внешний сервис уже склеил данные. Поэтому список ключей — не замена ревью. Ревью задаёт два вопроса: откуда взялось значение и можно ли ответить на диагностический вопрос без него? Если второй ответ «да», поле удаляется. Если «нет», для него фиксируется нормализованная форма, путь redaction и учебный пример, который проверяет именно этот путь.'),
paragraph('Практический порядок важнее количества масок. Сначала не передавать объект запроса. Затем выбрать короткий контекст. Затем заменить известные чувствительные узлы. Наконец, проверить сериализованный результат. При таком порядке новая интеграция не получает неявное право приносить любой JSON. Она должна добавить поле к контракту и объяснить его цену, иначе требование «сохранить для отладки» станет бесконечным исключением.'),
heading('Кардинальность проверяется в именах до первого запроса'),
paragraph('Высокая кардинальность редко выглядит угрозой в одном примере. Один номер заказа, одна строка внешней ошибки и один полный URL кажутся безобидными. Проблема появляется, когда они становятся формой поля: через неделю журнал содержит множество вариантов, где одинаковое событие нельзя отличить от нового. Поэтому правило проверяют не количеством строк, а источником значения. Если оно рождается из идентификатора, текста пользователя, query string или свободного исключения, ему не место в <code>event</code>, <code>route</code> или имени сервиса.'),
paragraph('Нормализация не обязана скрывать причину. Вместо текста можно выбрать <code>error.code</code> из маленького списка, вместо полного URL — route template, вместо динамического события — пару «устойчивое имя события + локальный технический код». Тогда человек всё ещё видит, куда идти: <code>adapter.response.rejected</code> и <code>TRAINING_SCHEMA_MISMATCH</code> ведут к адаптеру и его контракту. Но поиск не создаёт отдельную категорию на каждый учебный заказ или случайную фразу.'),
heading('Маршрут ревью для поля и записи'),
orderedList([
'Назвать диагностический вопрос, который должно закрыть новое поле; без вопроса поле не добавлять.',
'Отнести поле к базовому, ограниченному, redact или запрещённому классу.',
'Для строк с множеством значений выбрать нормализованный код, шаблон маршрута или словарное имя события.',
'Перед сериализацией прогнать синтетический объект через redaction и проверить точный JSON-результат.',
'По одному учебному request_id убедиться, что запись отвечает на вопрос без полного запроса, пользователя или секрета.',
'На ревью спросить, не используется ли высококардинальное поле как группа и не скрывается ли необязательная информация во вложенном объекте.',
]),
paragraph('Такой разбор связывает безопасность и диагностику без громких обещаний. В журнале остаётся ровно столько контекста, чтобы объяснить одну известную ветвь, а не восстановить целое production-событие. Следующее улучшение может потребовать отдельного формата ошибок, доступа к хранилищу или модели трассировки. Но до него полезно закрепить базовую дисциплину: событие имеет ограниченный словарь, один request_id ищется отдельно, а чувствительное значение не должно быть принято в журнал даже «временно».'),
],
[rfc5424, rfc8259, pinoApi, owaspLogging],
);
export const revisions = [practiceArticle, mechanismArticle, fieldArticle];
const currentFile = fileURLToPath(import.meta.url);
const invokedDirectly = process.argv[1] && resolve(process.argv[1]) === currentFile;
if (invokedDirectly) {
if (process.argv.includes('--print-revisions')) {
process.stdout.write(JSON.stringify(revisions));
} else if (process.argv.includes('--run-fixture')) {
process.stdout.write(JSON.stringify(runStructuredLogFixture()) + '\n');
}
}