* В Анкморе есть улица, на которой ночью не горит ни один фонарь. Воры её не любят: в темноте и им не видно, кто идёт следом. Город не раз собирался поставить там фонари и каждый раз решал, что раз ничего не случилось, то и смотреть не на что.
В уроке 97 Почтамт собрался в один слой, прошёл все тесты и упал в первый же полдень. Тесты не соврали: всё, что они проверяли, работало. Они не проверяли, что Почтамт расскажет, когда сломается. А рассказать ему было нечем: ни одной строки о том, кого он спрашивал, что услышал и на чём встал.
Журнал пишут не для себя. Его читает тот, кто придёт ночью, когда всё уже горит: дежурный, Рыдкулл, ты сам через полгода. У него нет времени угадывать. Ему нужны три вещи: насколько это серьёзно, что случилось и с кем. В Effect эти три вещи называются уровень, сообщение и пометки.
Журнал, который пишет эффект
На скорописи журнал это console.log. Он печатает строку сразу, в консоль, и больше о ней ничего не знает. В Effect запись в журнал это эффект, такой же, как все:
import { Effect } from 'effect';
const opening = Effect.gen(function* () {
yield* Effect.logInfo('окошко открыто');
yield* Effect.logWarning('очередь до реки');
yield* Effect.logDebug('в кассе 12 марок');
});
Effect.runPromise(opening);[07:12:04.191] INFO (#1): окошко открыто
[07:12:04.193] WARN (#1): очередь до рекиТретьей строки нет, и это не ошибка. У каждой записи есть уровень: Effect.logTrace, logDebug, logInfo, logWarning, logError, logFatal, по возрастанию серьёзности. По умолчанию минимальный уровень Info: всё, что ниже, отбрасывается, ещё не дойдя до консоли. Подробности для отладки пишутся в Debug и молчат, пока их не попросили:
import { Effect, Layer, References } from 'effect';
const loud = Layer.succeed(References.MinimumLogLevel, 'Debug');
Effect.runPromise(Effect.provide(opening, loud));References.MinimumLogLevel это ссылка с порогом. Слой с другим значением опускает порог для всего, что под ним запущено. Ночью дежурный включает Debug только у книги башен, а не у всего города.
Сам Effect.logInfo ничего не печатает. Он отдаёт запись логгеру, а логгер уже решает, куда её деть. Запись в журнал отделена от того, куда журнал пишется, точно так же, как в уроке 90 запрос был отделён от провода.
Пометки вместо склейки
Почтамт пишет «книга не отвечает». Про какую башню? На скорописи номер башни приклеивают к строке: 'книга не отвечает: ' + code. Ночью дежурный ищет все строки про T-5 глазами по тексту, и каждый автор клеил по-своему.
Effect держит контекст записи отдельно от её текста. Это пометки:
const deliver = (letter: number, tower: string) =>
Effect.gen(function* () {
yield* Effect.logInfo('спрашиваю книгу');
yield* Effect.logWarning('книга не отвечает');
}).pipe(Effect.annotateLogs({ letter, tower }), Effect.withLogSpan('доставка'));[07:12:04.196] INFO (#3) доставка=1ms: спрашиваю книгу { letter: 7, tower: 'T-5' }
[07:12:04.196] WARN (#3) доставка=1ms: книга не отвечает { letter: 7, tower: 'T-5' }Effect.annotateLogs вешает пометки на всё, что внутри эффекта, на любой глубине: на записи самого deliver и на записи сервисов, которые он позовёт. Писать номер письма в каждой строке руками не нужно. Effect.withLogSpan('доставка') добавляет к записям, сколько миллисекунд прошло с начала доставки.
Тексты при этом короткие и одинаковые: «книга не отвечает» всегда пишется одними словами. По таким записям дежурный ищет быстро: все записи с tower: 'T-5', все «книга не отвечает» за ночь.
Свой логгер
Строки выше печатает логгер по умолчанию. Почтамту нужен свой: журнал, который тест может прочитать, а Рыдкулл может отдать в любую систему сбора логов. Логгер делается функцией Logger.make:
import { Logger, References } from 'effect';
export interface Entry {
readonly level: string;
readonly message: string;
readonly annotations: Readonly<Record<string, unknown>>;
}
export const journalLogger = (write: (entry: Entry) => void) =>
Logger.make<unknown, void>((options) => {
const parts: ReadonlyArray<unknown> = Array.isArray(options.message) ? options.message : [options.message];
write({
level: options.logLevel,
message: parts.map(String).join(' '),
annotations: { ...options.fiber.getRef(References.CurrentLogAnnotations) },
});
});
export const journalLayer = (write: (entry: Entry) => void) => Logger.layer([journalLogger(write)]);Разберём.
Logger.makeполучает функцию от одной записи. Вoptionsлежит всё, что о записи известно:logLevel('Info','Warn','Debug'),message,date,causeи файбер, который писал.messageэто то, что передали вEffect.log. Если частей несколько,Effect.log('писем', 42), придёт массив, и журнал склеивает его через пробел.- Пометки логгер достаёт из файбера:
options.fiber.getRef(References.CurrentLogAnnotations). Это та же ссылка, в которую их положилannotateLogs. - Времени и номера файбера в записи журнала нет нарочно: запись зависит только от того, что случилось, и тест сравнивает её целиком.
Logger.layer([...])это слой, который заменяет логгеры по умолчанию. После него в консоль не уходит ничего, всё идёт вwrite. Если нужно и туда, и туда, есть опцияmergeWithExisting: true.
Для настоящего прода Effect уже знает готовые форматы: Logger.consoleJson пишет одну строку JSON на запись, Logger.formatStructured даёт объект с уровнем, временем, пометками и длительностями. Свой логгер нужен, когда журнал уходит туда, куда готовые не умеют, или когда его читает тест.
Тест журнала после этого пишется в несколько строк:
const entries: Entry[] = [];
const program = Effect.logInfo('окошко открыто').pipe(
Effect.annotateLogs({ window: 3 }),
Effect.provide(journalLayer((entry) => entries.push(entry))),
);
// после запуска: [{ level: 'Info', message: 'окошко открыто', annotations: { window: 3 } }]Под капотом
Журнал книги башен
Почтамт упал на книге башен. Значит, первое, что должно попасть в журнал, это каждый разговор с ней. Сервис TowerBook из урока 90 менять не нужно: его можно обернуть.
export const loggedBook = (book: TowerBook['Service']): TowerBook['Service'] => ({
lookup: (code) =>
Effect.logDebug('спрашиваю книгу').pipe(
Effect.andThen(book.lookup(code)),
Effect.tap((tower) => Effect.logInfo(tower.open ? 'башня открыта' : 'башня закрыта')),
Effect.tapError((error) => Effect.logWarning(`книга: ${error.reason}`)),
Effect.annotateLogs({ tower: code }),
),
});loggedBook берёт книгу и отдаёт книгу того же типа. Окошки не заметят подмены. Вопрос пишется в Debug: днём его не видно, ночью его включают. Ответ пишется в Info, беда в Warn с причиной словами из урока 90. Effect.tap и Effect.tapError смотрят на результат и не меняют его: башня идёт дальше, ошибка тоже. И всё под пометкой tower, одной строкой в конце.
Где тут дыра
const lookup = (code: string) =>
book.lookup(code).pipe(
Effect.tapError((error) => Effect.sync(() => console.log('книга ' + code + ': ' + error.reason))),
);На его примере работает: книга молчит про T-5, в консоли строка книга T-5: книга не отвечает. Теперь соседний пример, ночь открытия. Строк таких три тысячи, вперемешку с другими. Дежурный хочет все беды по T-5: ищет «T-5» по тексту и находит заодно письма, где T-5 упомянута в теме. Хочет только беды, без обычных ответов: уровня нет, у всех строк он одинаковый. Хочет проверить журнал в тесте: console.log не подменить слоем, только переопределить глобально. А пометку letter, которую окошко повесило выше, эта строка не видит вовсе: console.log о пометках не знает. Журнал Ринцвальда пишет, но читать его ночью нельзя.
Почтамт, этап 8
Почтамт заводит журнал. Новый модуль src/journal.ts: запись журнала, свой логгер, слой, который заменяет логгер по умолчанию, и журнал книги башен. Тесты пишут журнал в массив и сверяют уровни, тексты и пометки дословно, а в консоль не должно уйти ничего.
Практика
Глубже в архиве
Журналы, трассы и метрики на голом Node, без Effect, разобраны в уроке про производительность и телеметрию раздела про Node.
Дальше
К утру у Почтамта есть журнал. Рыдкулл листает ночные записи: книга не отвечает про T-5, про T-7, снова про T-5. Пондер смотрит через плечо.
История одного письма ждёт в следующем уроке.