Логи, по которым можно чинить; здоровье и мягкая остановка

В разработке console.log("пользователь " + id + " не смог войти") выглядит достаточно: строка читается, а если что — рядом отладчик. В проде отладчика нет, зато есть десятки тысяч таких строк от нескольких процессов, и вопросы к ним другие: сколько таких отказов было за час, всем пользователям или одному, что стояло в журнале за секунду до. Склеенная фраза ни на один из них не отвечает — по ней можно только искать подстроку, и первая же правка формулировки ломает поиск.

Поэтому строка лога пишется как запись: время, уровень, сообщение и поля. Сообщение при этом остаётся константой — «вход не удался», а не «вход не удался у 42». Всё переменное уезжает в поля, и тогда записи группируются по сообщению, отбираются по полю и считаются. Ещё два поля кладутся в каждую строку не думая: кто пишет (сервис, а лучше и версия) и по какому запросу — про второе будет следующий раздел.

Соберём такой логгер: функция печатает одну строку JSON на событие, а ветка делает из него дочерний логгер с дописанными полями. Прогноз: сколько строк выйдет и какие поля окажутся в последней?

const шаг = (() => {
  let t = Date.parse("2026-09-22T09:15:00Z");
  return () => new Date((t += 400)).toISOString();
})();

function логгер(общее) {
  const писать = (level, msg, поля = {}) => console.log(JSON.stringify({ t: шаг(), level, msg, ...общее, ...поля }));
  return {
    info: (msg, поля) => писать("info", msg, поля),
    error: (msg, поля) => писать("error", msg, поля),
    ветка: (ещё) => логгер({ ...общее, ...ещё }),
  };
}

const log = логгер({ svc: "api" });
log.info("слушаю", { port: 3000 });

const запроса = log.ветка({ requestId: "r-7", userId: 42 });
запроса.info("принят", { route: "POST /orders" });
запроса.error("база не ответила", { code: "ECONNREFUSED", ms: 812 });

Три строки, и каждая — самостоятельная запись. Общее поле svc проставлено один раз при создании логгера, requestId и userId — один раз на ветку, а в самих вызовах остались только те поля, которые относятся к этому событию. Это и есть дочерний логгер — приём, который есть у любой серьёзной библиотеки логов (у pino 10.3.1 это метод child, проверено) и придуман везде для одного: чтобы не протаскивать одни и те же поля в каждый вызов руками.

Сообщение — константа. «Пользователь 42 не найден» и «Пользователь 77 не найден» для любого сборщика логов два разных сообщения, и посчитать их вместе уже нельзя.

Обратная сторона полей — в них слишком легко положить лишнее. Самый частый способ — отдать в лог целый объект, который был под рукой. Прогноз: что окажется в журнале в каждой из трёх строк?

const пользователь = {
  id: 42,
  email: "kate@example.com",
  passwordHash: "$argon2id$v=19$m=65536,t=3,p=4$c29s$OeAo",
  token: "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiI0MiJ9",
};

const РАЗРЕШЕНО = ["requestId", "userId", "route", "status", "ms", "code"];
const отобрать = (поля) => Object.fromEntries(Object.entries(поля).filter(([имя]) => РАЗРЕШЕНО.includes(имя)));

const как_пишут = { requestId: "r-7", route: "POST /login", user: пользователь };
console.log(JSON.stringify(как_пишут));
console.log(JSON.stringify(отобрать(как_пишут)));
console.log(JSON.stringify(отобрать({ requestId: "r-7", route: "POST /login", userId: пользователь.id, status: 200 })));

В первой строке в журнал уехали хеш пароля, токен и почта — а журнал живёт дольше, чем инцидент, и лежит там, куда доступ шире, чем к базе. Вторая строка показывает, что отбор по списку разрешённых имён спасает не полностью: он выбросил user целиком, вместе с идентификатором, который как раз был нужен. Поэтому фильтр — это страховка от случайности, а не замена правилу: поля для журнала перечисляются руками, как в третьей строке.

Отдельный случай — ошибка. У неё в журнал кладут name, message и, если он есть, код первопричины из cause. Стек — по решению: он длинный и в JSON-строке нечитаем, но без него неизвестную ошибку не найти в коде. Разумный компромисс — стек только у уровня error и выше.

Один запрос проходит через контроллер, сервис, репозиторий и внешний вызов, и каждый из них пишет свои строки. В журнале они лежат вперемешку со строками соседних запросов — а на боевом сервере соседних запросов десятки в секунду. Сшивает их одно поле: идентификатор запроса, заведённый на входе и попавший во все строки, которые этот запрос породил.

Берётся он либо из заголовка, который дописал обратный прокси, либо создаётся самим приложением, если заголовка нет. И тем же значением полезно отвечать клиенту — заголовком ответа: тогда в жалобе «у меня не открылось» будет номер, по которому строки находятся за одну команду.

Вот кусок журнала с настоящего инцидента — восемь строк, четыре запроса. Задача — собрать из них картину. Прогноз: сколько запросов упало и по какой причине?

const журнал = [
  '{"t":"09:15:02.100","level":"info","msg":"принят","requestId":"r-1","route":"GET /notes"}',
  '{"t":"09:15:02.112","level":"info","msg":"ответ","requestId":"r-1","status":200}',
  '{"t":"09:15:02.310","level":"info","msg":"принят","requestId":"r-2","route":"POST /orders"}',
  '{"t":"09:15:02.330","level":"info","msg":"принят","requestId":"r-3","route":"GET /notes"}',
  '{"t":"09:15:02.480","level":"info","msg":"принят","requestId":"r-4","route":"POST /orders"}',
  '{"t":"09:15:03.122","level":"error","msg":"база не ответила","requestId":"r-2","code":"ECONNREFUSED"}',
  '{"t":"09:15:03.140","level":"error","msg":"база не ответила","requestId":"r-3","code":"ECONNREFUSED"}',
  '{"t":"09:15:03.151","level":"error","msg":"база не ответила","requestId":"r-4","code":"ECONNREFUSED"}',
];

const мс = (t) => Date.parse(`2026-09-22T${t}Z`);

const запросы = new Map();
for (const строка of журнал) {
  const событие = JSON.parse(строка);
  const свои = запросы.get(событие.requestId) ?? [];
  свои.push(событие);
  запросы.set(событие.requestId, свои);
}

const итоги = [...запросы.values()].map((свои) => ({
  id: свои[0].requestId,
  route: свои[0].route,
  исход: свои.at(-1).level === "error" ? свои.at(-1).code : свои.at(-1).status,
  длительность: мс(свои.at(-1).t) - мс(свои[0].t),
}));
for (const и of итоги) console.log(`${и.id} ${и.route} → ${и.исход} за ${и.длительность} мс`);

const отказы = итоги.filter((и) => typeof и.исход === "string");
const причины = new Set(отказы.map((и) => и.исход));
const маршруты = new Set(отказы.map((и) => и.route));
console.log(`отказов ${отказы.length} из ${итоги.length}; причин ${причины.size}; маршрутов ${маршруты.size}`);

Картина собралась из последней строки. Отказов три из четырёх, причина у всех одна, а маршрута два — значит, сломалась не ручка, а то, чем они обе пользуются. Отдельно стоит посмотреть на длительности: успевший запрос уложился в 12 мс, упавшие висели по 0,7–0,8 секунды и упали почти одновременно. Это подпись отказа общей зависимости: все ждали её таймаута, а не своей работы.

Собранная таким разбором сводка — то, с чего начинается отчёт об инциденте: что сломалось, когда, сколько запросов задело и по какому признаку они схожи. Дальше идёт состояние контейнеров и история выкатов — это уже разбор падения целиком, и там тот же журнал читается вместе с ними.

Время в журнале пишется в UTC и с миллисекундами. Локальный часовой пояс превращает сравнение строк от двух машин в задачу с подвохом, а секундной точности не хватает уже на десятке запросов в секунду.

import { AsyncLocalStorage } from "node:async_hooks";

const контекст = new AsyncLocalStorage();

// на входе: всё, что сделает обработчик, увидит этот объект
const обработать = (req, res) => контекст.run({ requestId: свежийId(req) }, () => маршрут(req, res));

// в логгере: поля берутся из хранилища, а не из параметров
const log = (msg, поля) => console.log(JSON.stringify({ t: new Date().toISOString(), msg, ...контекст.getStore(), ...поля }));

Писать логи приложение должно в stdout, и на этом его обязанности кончаются. Файл, ротация, сжатие, отправка в хранилище — дело того, кто запустил процесс: docker подбирает вывод сам, systemd отдаёт его журналу. Приложение, которое само открывает файл и само его вращает, придётся учить этому заново при каждом переезде, а при двух репликах ещё и выяснять, кто из них пишет в тот же файл.

У Nest логгер встроен, и он же отвечает за машинный формат. Посмотрим на один и тот же вызов при четырёх наборах настроек ConsoleLogger. Прогноз: сколько строк напечатает последний логгер и что в них будет?

import { ConsoleLogger } from '@nestjs/common';

// Логгер каркаса, каким он стоит по умолчанию: строка для человека.
const поумолчанию = new ConsoleLogger('Заказы');
поумолчанию.log('заказ принят', { orderId: 'A-17', userId: 42 });

// Тот же логгер в машинном виде — одна строка JSON на событие.
const машинный = new ConsoleLogger('Заказы', { json: true });
машинный.log('заказ принят', { orderId: 'A-17', userId: 42 });
машинный.error('база недоступна', { orderId: 'A-17', code: 'ECONNREFUSED' });

// Те же поля, но не отдельным объектом, а прямо в корне записи.
const плоский = new ConsoleLogger('Заказы', { json: true, flattenParams: true });
плоский.log('заказ принят', { orderId: 'A-17', userId: 42 });

// Как логгер вёл себя до Nest 12: разбор объектов-параметров выключен.
const безПараметров = new ConsoleLogger('Заказы', { json: true, structuredParams: false });
безПараметров.log('заказ принят', { orderId: 'A-17', userId: 42 });

[Nest] <pid>  - <дата>     LOG [Заказы] заказ принят { orderId: 'A-17', userId: 42 }
{"level":"log","pid":<pid>,"timestamp":<время>,"message":"заказ принят","context":"Заказы","params":{"orderId":"A-17","userId":42}}
{"level":"error","pid":<pid>,"timestamp":<время>,"message":"база недоступна","context":"Заказы","params":{"orderId":"A-17","code":"ECONNREFUSED"}}
{"level":"log","pid":<pid>,"timestamp":<время>,"message":"заказ принят","context":"Заказы","orderId":"A-17","userId":42}
{"level":"log","pid":<pid>,"timestamp":<время>,"message":"заказ принят","context":"Заказы"}
{"level":"log","pid":<pid>,"timestamp":<время>,"message":{"orderId":"A-17","userId":42},"context":"Заказы"}

Первая строка — вид по умолчанию: метка, pid, дата, уровень, контекст и объект, распечатанный util.inspect. Читать её человеку удобно, отбирать по полю — нечем. Вторая — тот же вызов с json: true: одна строка JSON, в ней level, pid, timestamp, message, context и объект-параметры отдельным полем params. Третья — то же для уровня error: такие записи ConsoleLogger пишет в stderr, а прогон складывает оба потока в один вывод. Четвёртая показывает, что делает flattenParams: поля переезжают в корень записи, и путь к ним становится короче на одно колено.

А последние две строки — одна запись. Так ведёт себя логгер с structuredParams: false, то есть ровно так он вёл себя до Nest 12: сообщение печатается без данных, а объект уезжает отдельной записью, у которой в поле message лежит сам объект. Сшить эти две строки нечем — ни номера запроса, ни признака, что они пара. В Nest 12 разбор параметров включён по умолчанию, и это едва ли не главная практическая новость релиза для тех, кто читает свои логи.

Цвета в первой строке появляются, когда json выключен, и пропадают, когда включён: раскрашенная строка перестала бы быть разбираемым JSON. Переменная NO_COLOR в окружении гасит их в любом случае — проверено, в трубу Nest по умолчанию всё равно пишет с кодами цвета.

Когда встроенного мало — берут pino. Дочерние логгеры у него из коробки, а вычищение секретных полей задаётся путями при создании: проверено на 10.3.1, redact: ["user.passwordHash"] подменяет значение на [Redacted] — ровно та страховка, о которой шла речь в первом разделе. Для одного сервиса это всё ещё оверкилл, и выбор между «хватает своего» и «пора брать библиотеку» разбирается на полке сервера.

«Приложение здорово» — два разных вопроса, и путать их дорого. Первый: жив ли процесс, отвечает ли он вообще. Второй: можно ли давать ему работу прямо сейчас. Ответы расходятся сплошь и рядом: процесс запустился, но ещё не прогрел соединения; база моргнула, а процесс цел; пришёл сигнал остановки — процесс жив и дослуживает начатое, но новых запросов ему давать уже нельзя.

Поэтому ручек две. Живость (/health) отвечает за сам процесс и не ходит никуда: если она начнёт спрашивать базу, одна медленная зависимость превратит проверку в приговор — оркестратор убьёт процесс ровно тогда, когда он и так не справляется. Готовность (/ready) отвечает за работу и зависимости спрашивает, но бережно: с кешем и коротким таймаутом, потому что стучатся в неё несколько источников раз в несколько секунд.

Соберём обе на модели с часами вместо времени. Прогноз: какой код вернёт /ready сразу после того, как база перестала отвечать?

const состояние = { останавливаемся: false, базаОтвечает: true };
const часы = { сейчас: 0 };
let проба = { когда: -Infinity, ответ: 0 };

// живость ничего не спрашивает: если она пойдёт в базу, одна медленная
// зависимость превратит проверку в приговор всему процессу
const живость = () => 200;

const готовность = () => {
  if (состояние.останавливаемся) return 503;
  if (часы.сейчас - проба.когда >= 2000) проба = { когда: часы.сейчас, ответ: состояние.базаОтвечает ? 200 : 503 };
  return проба.ответ;
};

const спросить = (что) => console.log(`${часы.сейчас} мс: /health ${живость()}, /ready ${готовность()} — ${что}`);

спросить("старт");
часы.сейчас = 500;
состояние.базаОтвечает = false;
спросить("база перестала отвечать");
часы.сейчас = 2600;
спросить("с прошлой пробы прошло больше двух секунд");
часы.сейчас = 5000;
состояние.базаОтвечает = true;
спросить("база снова отвечает");
часы.сейчас = 7100;
состояние.останавливаемся = true;
спросить("пришёл сигнал остановки");

Сразу после отказа готовность ещё отвечает 200 — ответ пришёл из кеша, снятого до отказа. Это не баг, а цена: проба не ходит в базу на каждый запрос, и её картина отстаёт на срок кеша. Срок и выбирают из этого: две секунды — это до двух секунд запоздалого «готов», зато база не получает лишней нагрузки от проверок. А на сигнале остановки готовность переключается сразу и без всяких проб: тут спрашивать нечего, решение уже принято.

Этот порядок и есть главная польза от второй ручки: /ready отвечает 503 раньше, чем процесс начнёт умирать. Балансировщик или прокси успевает увести трафик, и остановка застаёт сервер без новых запросов. Без готовности снятие с ротации происходит по факту отказа соединения — то есть уже на чьих-то запросах.

Снаружи ручку здоровья опрашивает проба контейнера. В боевом репозитории автора она лежит не в compose, а в образе — и едет вместе с ним:

# apps/api/Dockerfile автора: последняя стадия образа
HEALTHCHECK --interval=30s --timeout=5s --start-period=15s --retries=3 \
  CMD node -e "fetch('http://127.0.0.1:8000/api/health').then(r=>process.exit(r.ok?0:1)).catch(()=>process.exit(1))"

# то же самое в compose — так пишут, когда образ чужой и править его нельзя.
# stop_grace_period здесь не про здоровье: это срок, который docker даёт
# процессу после SIGTERM, прежде чем послать SIGKILL (по умолчанию 10 секунд)
services:
  api:
    healthcheck:
      test: ['CMD', 'node', '-e', "fetch('http://127.0.0.1:8000/api/health').then(r=>process.exit(r.ok?0:1)).catch(()=>process.exit(1))"]
      interval: 30s
      timeout: 5s
      start_period: 15s
      retries: 3
    stop_grace_period: 20s

Проба написана на node, потому что в образе на node:24-slim нет ни curl, ни wget; решает не её вывод, а код выхода. Остальное — расписание: как часто спрашивать, сколько ждать ответа, сколько отказов подряд делают контейнер больным и сколько времени в начале отказы не считать. Что docker делает с больным контейнером (и чего не делает), разобрано в разделе про пробу, которая меряет не то; про последнюю стадию образа — там же в главе о слоях.

Ручка здоровья обязана отвечать и когда база лежит: на то она и живость. Приложение, которое не дождалось конфигурации, — другое дело: ему честнее упасть на старте, до первого запроса.

Последнее уточнение про адреса: обе ручки должны отвечать быстро и без авторизации — пробе негде взять токен. Наружу их не публикуют: проба ходит изнутри сети контейнеров, а через прокси адрес здоровья становится первым, что находит сканер. Строгая проверка конфигурации перед стартом — отдельная тема первой статьи про загрузку.

Выкат новой версии выглядит так: docker посылает старому контейнеру SIGTERM, ждёт stop_grace_period и, если процесс ещё жив, посылает SIGKILL — сигнал, который не перехватывается. Всё, что приложение успеет сделать, оно сделает в этом окне. Не успеет — оборванные ответы, незакрытые транзакции и запись, которая была на середине.

Первая же деталь меняет поведение процесса целиком. У SIGTERM в Node есть действие по умолчанию — завершиться с кодом 143; но стоит повесить на сигнал слушателя, и действие по умолчанию отменяется: процесс остаётся жить, и выход теперь ваша забота. Проверено на node 26.5.0: без слушателя процесс уходит немедленно с кодом 143, со слушателем — продолжает работать и печатать. Слушатель, который забыл выйти, превращает остановку в ожидание SIGKILL.

Порядок действий внутри окна всегда один: снять себя с ротации (готовность отвечает 503), закрыть приём новых запросов, дослужить те, что в полёте, закрыть пул и остальные ресурсы, выйти. Соберём это на модели: сигналы разносит EventTarget — родственник излучателя, который мы собирали сами, только штатный; запросы — множество имён, пул — счётчик занятых соединений. Прогноз: что напечатает запрос, пришедший после сигнала, и когда закроется пул?

const сигналы = new EventTarget();
const вПолёте = new Set();
let принимаем = true;

const пул = {
  занято: 0,
  закрыт: false,
  взять() {
    if (this.закрыт) throw new Error("пул закрыт");
    this.занято += 1;
  },
  вернуть() {
    this.занято -= 1;
  },
  закрыть(причина) {
    if (this.закрыт) return;
    this.закрыт = true;
    console.log(`пул закрыт (${причина}), занято ${this.занято}`);
  },
};

const принять = (имя) => {
  if (!принимаем) return console.log(`${имя}: 503`);
  вПолёте.add(имя);
  пул.взять();
};

const ответить = (имя) => {
  if (!вПолёте.delete(имя)) return;
  пул.вернуть();
  console.log(`${имя}: 200`);
  if (!принимаем && вПолёте.size === 0) сигналы.dispatchEvent(new Event("пусто"));
};

сигналы.addEventListener("SIGTERM", () => {
  принимаем = false;
  console.log(`SIGTERM: в полёте ${вПолёте.size}`);
});
сигналы.addEventListener("пусто", () => пул.закрыть("все ответили"));

принять("r-1");
принять("r-2");
сигналы.dispatchEvent(new Event("SIGTERM"));
принять("r-3");
ответить("r-1");
ответить("r-2");

Запрос после сигнала получает 503, а не обрыв соединения: это важная разница — клиент видит понятный отказ и может повторить его на другой реплике. Два запроса в полёте дослуживаются как обычно, и пул закрывается сам, когда счётчик в полёте дошёл до нуля. Обратите внимание, что закрывает его не обработчик сигнала, а событие «пусто»: обработчику в момент сигнала закрывать нечего, он только переводит сервер в режим остановки.

Чего в модели нет — крайнего срока. Если один запрос завис на внешнем вызове без таймаута (та самая почта, которая приняла соединение и молчит), счётчик до нуля не дойдёт никогда, и процесс будет ждать SIGKILL, ничего не закрыв. Поэтому вместе с сигналом заводят таймер на срок заведомо меньше stop_grace_period: вышло время — закрываем пул и выходим, записав в журнал, сколько запросов бросили. Это первая задача статьи.

Таймер крайнего срока в Node ставят с unref: без него сам таймер держит процесс живым и мешает ему выйти раньше, если все запросы дослужили быстро.

В Nest всё это уже написано, но включается одной строкой. Без неё каркас на сигналы не подписывается, и хуки завершения не вызываются вовсе:

// apps/api/src/main.ts автора: без этой строки onApplicationShutdown не вызовут,
// пул Postgres и сокеты SMTP останутся открытыми, а контейнер не завершится по сигналу
app.enableShutdownHooks();

// провайдеру, которому есть что закрыть, остаётся объявить хук
@Injectable()
export class Db implements OnApplicationShutdown {
  async onApplicationShutdown(signal?: string) {
    await this.pool.end();
  }
}

Проверено 22.09.2026 на Nest 12.0.3: с enableShutdownHooks сигнал доходит до хука, асинхронный хук дожидаются, и только потом процесс выходит; без неё хук не зовут совсем. Код выхода в обоих случаях один и тот же — 143, то есть по коду выхода не отличить процесс, который аккуратно закрылся, от процесса, который просто умер. Отличить их можно только по строке в журнале, которую пишет хук, — поэтому её и пишут.

Перенесём модель на настоящий node:http — тот самый разбор запросов, который мы писали руками, только готовый. У него для остановки есть server.close(): он перестаёт принимать новые соединения и зовёт колбэк, когда закрылось последнее. Звучит как готовая мягкая остановка, и в этом месте прячется сюрприз.

В прогоне два одинаковых сервера. Оба получают один SIGTERM, посланный процессом самому себе, у обоих в этот момент по запросу в полёте. Расходятся они одной строкой: сервер B, ответив последнему запросу, ещё раз убирает простаивающие соединения, сервер A — нет. Прогноз: что получит запрос, пришедший после сигнала, что получит запрос в полёте и кто из серверов закроется быстрее секунды?

import http from 'node:http';
import { once } from 'node:events';
import { setTimeout as sleep } from 'node:timers/promises';

// Два одинаковых сервера. Расходятся одной строкой: B убирает простаивающие
// соединения ещё раз — когда отвечен последний запрос.
function поднять(имя, убиратьПослеОтвета) {
  const счёт = { останавливаемся: false, вПолёте: 0, последнийОтвет: 0 };

  const сервер = http.createServer(async (запрос, ответ) => {
    счёт.вПолёте += 1;
    await sleep(600);
    ответ.end(`ответ ${имя} на ${запрос.url}\n`);
    await once(ответ, 'finish');
    счёт.вПолёте -= 1;
    счёт.последнийОтвет = Date.now();
    if (убиратьПослеОтвета && счёт.останавливаемся && счёт.вПолёте === 0) сервер.closeIdleConnections();
  });

  сервер.listen(0, '127.0.0.1');
  // срок считается прямо в событии close: до печати итога очередь доходит своим
  // чередом, и замер по ней был бы не о том
  const быстро = once(сервер, 'close').then(() => Date.now() - счёт.последнийОтвет < 1000);

  return {
    счёт,
    адрес: once(сервер, 'listening').then(() => сервер.address()),
    остановить() {
      счёт.останавливаемся = true;
      сервер.close();
    },
    async итог() {
      return `${имя}: закрылся быстрее секунды — ${(await быстро) ? 'да' : 'нет'}`;
    },
  };
}

const a = поднять('A', false);
const b = поднять('B', true);
const адресA = await a.адрес;
const адресB = await b.адрес;
const url = ({ address, port }, путь) => `http://${address}:${port}${путь}`;
console.log(`A слушает ${адресA.address}:${адресA.port}, B слушает ${адресB.address}:${адресB.port}`);

process.on('SIGTERM', () => {
  console.log(`SIGTERM: в полёте запросов — A ${a.счёт.вПолёте}, B ${b.счёт.вПолёте}`);
  a.остановить();
  b.остановить();
});

const вПолёте = [fetch(url(адресA, '/slow')), fetch(url(адресB, '/slow'))];
await sleep(100);
process.kill(process.pid, 'SIGTERM');
await sleep(100);

try {
  const ответ = await fetch(url(адресA, '/fast'));
  console.log(`запрос после сигнала: ${ответ.status}`);
} catch (ошибка) {
  console.log(`запрос после сигнала: ${ошибка.cause?.code ?? ошибка.message}`);
}

for (const запрос of вПолёте) {
  const ответ = await запрос;
  console.log(`запрос в полёте: ${ответ.status} ${(await ответ.text()).trim()}`);
}
console.log(await a.итог());
console.log(await b.итог());

A слушает 127.0.0.1:<порт>, B слушает 127.0.0.1:<порт>
SIGTERM: в полёте запросов — A 1, B 1
запрос после сигнала: ECONNREFUSED
запрос в полёте: 200 ответ A на /slow
запрос в полёте: 200 ответ B на /slow
A: закрылся быстрее секунды — нет
B: закрылся быстрее секунды — да

Первые две ожидаемые части сошлись: запрос, пришедший после сигнала, получил ECONNREFUSED — слушающий сокет уже закрыт, соединение некому принять; запросы в полёте дослужились и получили свои 200. Процесс вышел с нулём. А вот сроки разошлись: B закрылся быстрее секунды, A — нет. Отдельный замер тем же кодом: событие close у A приходило через 3008 мс после последнего ответа, при повторе — через 3013.

Причина в том, что делает close() на самом деле. Он закрывает слушающий сокет и те соединения, которые простаивают в момент вызова. Соединение, по которому шёл запрос, в этот момент занято — его он не трогает; а когда через полсекунды запрос дослужился и соединение стало простаивающим, закрывать его уже некому: разовая уборка прошла. Соединение живо по keep-alive, и close ждёт, пока кто-нибудь повесит трубку.

Три секунды — это клиент. Замер на node 26.5.0: при keepAliveTimeout сервера 3, 5, 7, 10 и 20 секунд ожидание вышло 1, 3, 5, 8 и 18 секунд — ровно на две меньше объявленного. Сервер сообщает свой срок заголовком Keep-Alive: timeout=5, а fetch вешает трубку с запасом в две секунды. А если на том конце клиент, который сам не уходит, соединение закрывает уже сервер — по своему keepAliveTimeout из таблицы сроков: в замере с сырым сокетом это шесть секунд после ответа при сроке в пять.

Лечится это одной строкой, и вариантов два. Первый — сервер B: после последнего ответа позвать closeIdleConnections() ещё раз, когда соединение уже освободилось. Второй — на время остановки отвечать с заголовком Connection: close: тогда клиент закроет соединение сам, получив ответ. Оба честнее, чем просто уменьшить keepAliveTimeout: это срок для всех соединений и на всё время работы, а проблема — на секунды остановки.

server.close не обрывает запрос в полёте — это единственное, что он обещает. Всё остальное в остановке приходится дописывать самому.