Бюджеты завершения и наблюдаемость graceful shutdown

← назад к разделу

Выкат прошёл, а в логе одного из pod остановка обрывается на полуслове: последняя строка — про дрейн HTTP, дальше тишина. Kubernetes подождал свои 60 секунд и прислал SIGKILL. Что именно не успело — планировщик, пул соединений, недописанная пачка Kafka — по такому логу не понять, а значит, непонятно и что чинить.

Остановка перестаёт быть гаданием, когда известны три вещи: как складывается бюджет, сколько он занимает на самом деле и что сокращать, когда не укладывается.

Сложение видно на одной шкале: каждая группа укладывается в свой лимит, а их сумма — нет; и те же группы после того, как сократили порции Kafka и планировщика.

Откуда берётся 60 секунд

Kubernetes при удалении pod ждёт terminationGracePeriodSeconds и после этого убивает процесс. По умолчанию это 30 секунд, а одни только пауза preStop и дрейн HTTP по умолчанию дают 10 + 30, поэтому дальше в разделе бюджет поднят до 60 — как он выбран, разобрано в статье про Kubernetes. Вопрос здесь другой: на что эти 60 секунд уходят и кто за какой кусок отвечает.

Shutdown состоит из нескольких шагов, и у каждого своя граница — но ручек меньше, чем шагов:

На вторую и третью строку стоит посмотреть внимательно: отдельного таймаута нет ни у Kafka-контейнеров, ни у дрейна HTTP. Обе группы ограничены одним и тем же spring.lifecycle.timeout-per-shutdown-phase — одним свойством на всё приложение. Собственный срок есть только у планировщика и у пула @Async-задач.

Теперь сложим не лимиты, а фактические длительности: preStop 10 + Kafka 15 + дрейн HTTP 25 + планировщик 20 — 70 секунд, больше бюджета, хотя ни одна группа свой лимит не превысила. Так выходит потому, что Spring не выключает всё разом, а идёт группами, одна за другой: пока не остановилась предыдущая, следующая не начинается. Длительности складываются, а timeout-per-shutdown-phase стоит на каждой группе отдельно — он не ограничивает сумму, а наоборот, выдаёт каждой одинаково щедрый потолок. Общего таймаута остановки в Spring нет вовсе; единственная сумма, которая существует, — terminationGracePeriodSeconds снаружи, и считать её приходится вам.

Порядок групп задаётся номерами фаз — чем больше номер, тем раньше группу гасят: контейнеры Kafka (Integer.MAX_VALUE − 100), затем дрейн веб-сервера (Integer.MAX_VALUE − 1024), последними планировщик и @Async (Integer.MAX_VALUE / 2). С интуицией это совпадает только наполовину. «Сначала перестаём брать новую работу извне» верно про Kafka. А планировщик и @Async гасят после дрейна HTTP, а не до; если у них включён await-termination, ожидание съезжает ещё дальше — на уничтожение бинов. Фоновая задача спокойно работает в тот момент, когда HTTP уже закрыт и pod давно не принимает трафик, — и именно её SIGKILL обрывает первой.

Сколько остановка длится сейчас

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

10:00:10.012 INFO c.e.ShutdownObserver : Graceful shutdown started, deadline=60s
10:00:25.341 INFO o.s.k.l.KafkaMessageListenerContainer : orders: Consumer stopped
10:00:25.350 INFO o.s.b.w.e.tomcat.GracefulShutdown : Commencing graceful shutdown. Waiting for active requests to complete
10:00:50.118 INFO o.s.b.w.e.tomcat.GracefulShutdown : Graceful shutdown complete

Первая строка — своя, из ContextClosedEvent (код ниже); от неё считают всё остальное. Consumer stopped пишет Spring для каждого потребителя с именем группы впереди: 15 секунд от старта до этой строки и есть длительность группы Kafka. Дрейн HTTP обрамлён парой строк от Tomcat — Commencing graceful shutdown и Graceful shutdown complete, здесь 25 секунд; если бы запросы не успели, вместо второй стояло бы Graceful shutdown aborted with one or more requests still active. У планировщика и @Async своей строки нет: их группа — промежуток от Graceful shutdown complete до строк HikariCP HikariPool-1 - Shutdown initiated... и Shutdown completed., потому что пул закрывают уже при уничтожении бинов. Если ожидание задач тоже съехало на уничтожение бинов через await-termination, две границы перемешиваются, и точную даёт только своя строка в @PreDestroy бина с задачей.

В логе выше строк HikariCP нет, и это главный признак: они — последнее, что приложение пишет о себе, и если их нет, процесс до конца не дошёл сам. Полную длительность до выхода приложение записать не может в принципе: тот, кто пишет лог, сам является бином и уничтожается в общей очереди. Зато Spring сам сообщает, когда группа не уложилась в свой лимит, — строкой Shutdown phase 2147483547 ends with 1 bean still running after timeout of 30000ms: [...], где номер и есть фаза группы, а в скобках — имена бинов, которых не дождались.

Две вещи в лог приложения не попадают. Пауза preStop идёт до SIGTERM: её 10 секунд лежат между событием Killing в kubectl describe pod и первой строкой остановки. И сам SIGKILL: его выдаёт код выхода процесса — JVM, поймавшая SIGTERM и завершившаяся сама, выходит с кодом 143, убитая — с кодом 137. Код kubelet записывает в состояние контейнера, но при выкате pod удаляют из API сразу после выхода, и посмотреть не успеть; надёжнее признак из лога — нет строк HikariCP, значит, убили.

Что делать, если не укладываетесь

Первый инстинкт — поднять terminationGracePeriodSeconds до 90 или 120 секунд: цифра одна, и остановка перестанет обрываться. Ошибка в том, что этот бюджет платят не один раз, а на каждом pod и в каждой операции, которая pod гасит.

Выкат состоит из двух половин, и остановка — только одна из них. При maxSurge: 1, maxUnavailable: 0 замена одного pod идёт так: новый pod поднимается — JVM стартует 20–30 секунд, потом его должна пройти readiness, — и лишь после этого старый начинает остановку, до 60 секунд. Полторы минуты на pod; десять реплик — четверть часа выката, а с бюджетом 120 — почти полчаса. Всё это время в строю обе версии кода против одной базы, и чем длиннее окно, тем больше запросов старой версии увидят новую схему.

Вторая операция, которая платит тот же бюджет, — вывод узла из работы. kubectl drain (то же делает автомасштабирование узлов, когда убирает лишний) выселяет pod с узла через Eviction API, а PodDisruptionBudget говорит, сколько реплик сервиса можно держать недоступными одновременно. С maxUnavailable: 1 в PDB pod вашего сервиса уходят с узла строго по очереди, каждый со своим полным бюджетом, а drain по умолчанию ждёт без ограничения по времени. Пять pod сервиса на узле при бюджете 120 — десять минут на узел; обновление кластера на двадцать узлов растягивается на часы, и ждёт их тот, кто его делает.

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

• Kafka — max.poll.records: 500 → 100: пачка — единица, которую контейнер обязан доработать до конца, и с меньшей пачкой listener закончит за 5 секунд вместо 15.
• Планировщик — размер порции @Scheduled-задачи, 50 записей вместо 500: планировщик ждёт ровно текущую итерацию, и группа уложится в 5 секунд вместо 20.
• Дрейн HTTP — ручки нет: его длина равна самому долгому запросу, который был в работе в момент SIGTERM. 25 секунд дрейна значат, что у вас есть запросы по 25 секунд, и лечат их разбиением на короткие операции, а не таймаутом.
• preStop — не трогать: его 10 секунд не ваша работа, а время kube-proxy на обновление маршрутов; убрать их — вернуть 502 на каждый выкат.

Двух сокращений хватает: 10 + 5 + 25 + 5 = 45 секунд плюс пара секунд на закрытие пула соединений — 47 при бюджете 60, и порог алерта в 50 секунд остаётся нетронутым.

Оговорка про эту «пару секунд»: она верна, только если к моменту закрытия в пуле не осталось занятых соединений. Если осталось — HikariCP до 10 секунд добивает их в цикле, и хвост из двух секунд превращается в десять. Это ещё одна причина не подпускать длинные транзакции к концу остановки.

Метрика длительности завершения

Лог отвечает на вопрос «что случилось» по одному pod и уже после того, как случилось. Вопрос «мы приближаемся к бюджету?» задают сразу по всем pod и заранее — это работа графика, и для него нужна метрика. Gauge, который растёт на протяжении всей остановки, регистрируют в тот же момент, когда пишут первую строку:

@Component
@Slf4j
public class ShutdownObserver {

    private final MeterRegistry meterRegistry;
    private final long deadlineSeconds;

    public ShutdownObserver(MeterRegistry meterRegistry,
                            @Value("${app.shutdown.deadline-seconds:60}") long deadlineSeconds) {
        this.meterRegistry = meterRegistry;
        this.deadlineSeconds = deadlineSeconds;
    }

    @EventListener(ContextClosedEvent.class)
    public void onShutdown() {
        var startedAt = System.currentTimeMillis();
        log.info("Graceful shutdown started, deadline={}s", deadlineSeconds);
        Gauge.builder("app.shutdown.duration", () -> (System.currentTimeMillis() - startedAt) / 1000.0)
            .baseUnit("seconds")
            .register(meterRegistry);
    }
}

Откуда берётся дедлайн. Свойства terminationGracePeriodSeconds в Spring нет — Kubernetes приложению своего бюджета не сообщает. Значение приходится продублировать руками, переменной окружения рядом с самим полем в манифесте:

spec:
  terminationGracePeriodSeconds: 60
  containers:
    - name: app
      env:
        - name: APP_SHUTDOWN_DEADLINE_SECONDS
          value: "60"

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

Почему имя метрики через точки. app.shutdown.duration — это стиль Micrometer. Подчёркивания и суффикс _seconds подставит экспортёр, и в Prometheus метрика приедет как app_shutdown_duration_seconds. Напишете прометеевское имя прямо в коде — при переезде на другой бэкенд оно поедет вместе с вами и станет кривым.

Запросы в Prometheus — график по сервисам и порог алерта:

# Сколько длился shutdown по сервисам
max by (service) (app_shutdown_duration_seconds)

# Предупреждение, если подходим к бюджету
max(app_shutdown_duration_seconds) > 50

Порог 50 из 60 оставляет 10 секунд запаса — ровно столько, сколько стоит одна лишняя пачка Kafka или один долгий запрос. Сработал — значит, у какого-то pod остановка перевалила за 50 секунд, и дальше метрика не нужна: открываете лог этого pod, по маркерам находите группу, которая съела больше всех, и крутите её ручку в порядке из предыдущего раздела. Метрика говорит «где-то близко», лог — «что именно».

Честная оговорка: одной метрики мало. Gauge появляется в момент ContextClosedEvent, а pod после этого живёт меньше минуты — Prometheus со стандартным интервалом сбора успеет снять значение в лучшем случае один раз, а чаще ни разу. Поэтому длительность остановки собирают по строкам лога, а если метрика нужна именно как метрика — её отправляют сами, через push-gateway или по OTLP, перед выходом.

Почему получили SIGTERM — как разобраться

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

Выкат новой версии — самая частая причина и единственная плановая: pod много, идут по очереди, и общая длительность выката равна сумме их бюджетов — именно здесь окупается каждая сэкономленная секунда. Уменьшение реплик через HPA случается, когда упал трафик, то есть чаще ночью, и pod для остановки выбирается без оглядки на то, что на нём крутится: если фоновая задача длиннее бюджета, ночью она и оборвётся. kubectl delete pod руками даёт тот же бюджет, что выкат, но обычно означает, что кто-то чинит инцидент и на pod могло быть что угодно. Обслуживание узла — kubectl drain или автомасштабирование узлов — гасит pod по очереди через PodDisruptionBudget, и здесь бюджет умножается на число pod сервиса на узле.

В коде определять причину бессмысленно — это информация уровня инфраструктуры, приложение только фиксирует факт строкой на ContextClosedEvent, и она у нас уже есть в ShutdownObserver. Причину ищут в kubectl describe pod <имя>: раздел Events показывает, кто и почему удалил pod:

Events:
  Type    Reason             Age   From                       Message
  ----    ------             ----  ----                       -------
  Normal  Killing            2m    kubelet                    Stopping container app
  Normal  ScalingReplicaSet  10m   deployment-controller      Scaled down replica set

Кто именно выполнил kubectl delete, покажет только audit log Kubernetes, если он включён.

Когда бюджет не поможет

Всё выше работает, пока процесс получает SIGTERM. В четырёх случаях его нет, и никакая настройка остановки не спасёт. Контейнер, вышедший за лимит памяти, получает от ядра SIGKILL, минуя kubelet и любые таймауты, — в kubectl describe pod это Reason: OOMKilled и код 137, и лечится это памятью. Тот же SIGKILL с тем же кодом 137 приходит от kubelet, когда бюджет истёк: всё, что не успело, оборвано на середине. kubectl delete pod --grace-period=0 --force удаляет pod немедленно, без SIGTERM и без паузы. И наконец, узел, который потерял питание или упал ядром, не шлёт ничего: pod объявят пропавшим через несколько минут, а его работа исчезнет молча.

Спасает здесь не остановка, а то, как устроена сама работа. Потребитель Kafka с ручным подтверждением после обработки: offset не зафиксирован — сообщение придёт снова, и получатель обязан отсеять дубль. Outbox: строки без отметки об отправке заберёт следующий запуск relay. HTTP-клиенты с повтором и ключом идемпотентности, чтобы повтор не создал второй заказ. Правило простое: код должен переживать SIGKILL, а graceful shutdown только уменьшает, сколько работы придётся повторить. Как именно переживать — в статьях про идемпотентность и outbox.

Обычные события завершения — не ERROR

Распространённая ошибка — не в библиотеках, а в настройке логов на своей стороне: обычные сообщения о завершении попадают в поток ошибок. Выглядит это так:

ERROR c.example.OrderConsumer - Consumer stopped, interrupting poll
ERROR c.example.OutboxRelay  - Relay shutting down, 12 events pending

Это штатные события каждого выката. На уровне ERROR они уходят в канал дежурного — Slack или PagerDuty. Десяток ложных алертов на каждый деплой, и команда учится их не читать; когда случается настоящий сбой, реакция запаздывает.

Лечение зависит от того, чей это лог. Строки выше пишут свои классы, и способ тут один — поправить сам вызов: log.error(...) на log.info(...). Уровень логгера не поможет, и важно понимать почему. <logger name="..." level="WARN"/> в logback-spring.xml — это порог: событие ниже порога отбрасывается до того, как дойдёт до appender, а событие на пороге и выше проходит как есть. Порог отсекает снизу; уже написанный ERROR он не понизит и в канал алертов пропустит.

Порог нужен для другого — когда на остановке шумит чужая библиотека. Клиент Kafka на закрытии каждого потребителя пишет десяток INFO-строк: снятие партиций, выход из группы, отключение метрик. При десяти потребителях это сотня строк, среди которых искать маркеры остановки неудобно. Порог их убирает:

<logger name="org.apache.kafka.clients" level="WARN"/>

Оговорка: порог убирает и полезное. Маркеры из раздела про измерение — INFO-строки пакетов org.springframework.kafka.listener, org.springframework.boot.web.embedded.tomcat и com.zaxxer.hikari; поднимете им порог до WARN — потеряете раскладку остановки. Строку Consumer stopped пишет Spring, а не клиент Kafka, поэтому порог на org.apache.kafka.clients её не трогает. На уровне ERROR остаются только настоящие проблемы: принудительное завершение с потерей данных, разрыв соединения в неожиданный момент, исключения, которых при штатном завершении быть не должно.

Глубже: как проверить: нагрузка во время выката и счётчик 502расширенное

Всё в этом разделе описано словами и настройками, а работает ли оно, узнают одним способом: под нагрузкой во время выката, и не на проде первым.

Локально, за минуту. docker stop -t 60 my-app отправляет SIGTERM и ждёт до минуты; в логе должны идти строки Commencing graceful shutdown, остановка слушателей, HikariPool-1 - Shutdown completed, и всё это быстрее, чем таймаут. kill -TERM $(pgrep -f order-service) делает то же без Docker и показывает, доходит ли сигнал до JVM, о чём раздел про PID 1. Если вместо строк тишина и Exited (137), дальше проверять нечего.

На стенде, под нагрузкой. Нагрузочный инструмент (k6, vegeta, Gatling) держит постоянный поток запросов, сто в секунду с реальными POST, а в это время идёт kubectl rollout restart deployment/order-service. Критерий один: ноль ответов 5xx за окно выката и задержка p99 в пределах бюджета. Считают не в самом инструменте, а на входе: метрика ingress по кодам за окно, потому что обрыв соединения инструмент видит как сетевую ошибку, а пользователь как 502 от прокси. Тот же прогон повторяют с kubectl delete pod, чтобы проверить не выкат, а неожиданную остановку, и с drain узла, чтобы проверить PodDisruptionBudget.

k6 run --vus 20 --duration 3m load.js &
kubectl rollout restart deployment/order-service && kubectl rollout status deployment/order-service
wait

В конвейере. Проверка живёт в отдельном шаге на временном окружении (namespace на ветку или предварительный стенд): выкат предыдущей версии, нагрузка, выкат новой поверх, сравнение счётчика 5xx с нулём, и шаг красный при любом отличии. Это дороже юнит-тестов и дешевле одного инцидента; запускают его не на каждый коммит, а перед выпуском и при любом изменении настроек остановки, проб и terminationGracePeriodSeconds.

Что смотреть кроме кодов. Метрику длительности остановки из раздела выше: она обязана быть меньше бюджета с запасом. Число сообщений, обработанных дважды, если есть идемпотентный потребитель: рост при выкате означает, что слушатели не дождались коммита. И журнал за окно выката без ERROR от штатных событий остановки, о чём последний раздел этой статьи.

Коротко

• Общего таймаута остановки в Spring нет: timeout-per-shutdown-phase стоит на каждой группе, группы гасятся по очереди, и 10 + 15 + 25 + 20 = 70 перерастает бюджет 60 без единого превышения лимита.
• Раскладку снимают по логу: своя строка на ContextClosedEvent, Consumer stopped, пара строк Tomcat вокруг дрейна, строки HikariCP в конце. Нет строк HikariCP — процесс убили; снаружи то же скажет код выхода 137 вместо 143.
• terminationGracePeriodSeconds: 120 платят на каждом pod: выкат и kubectl drain растягиваются, окно двух версий против одной базы удлиняется. Сокращают порции Kafka и @Scheduled, долгие запросы разбивают, preStop не трогают.
• Метрика с порогом 50 из 60 нужна для «заранее и по всем pod», но gauge на ContextClosedEvent Prometheus обычно снять не успевает — лог первичен, метрику отправляют push-ем.
• OOMKilled, истёкший бюджет, --force и смерть узла обходятся без SIGTERM: спасают ручной ack, outbox и идемпотентность, а не таймауты.
• Своим строкам про штатное завершение — INFO прямо в коде: порог логгера отсекает снизу и ERROR не понизит; порогом гасят чужой шум, не трогая пакеты, по которым меряют остановку.
• Проверяют под нагрузкой: docker stop -t 60 и kill -TERM локально по строкам в логе, k6 или vegeta во время rollout restart, delete pod и drain на стенде; критерий ноль 5xx на ingress за окно выката, шаг конвейера перед выпуском.

Что почитать дальше

• JVM и Spring конфигурация — откуда берутся фазы, timeout-per-shutdown-phase и порядок уничтожения бинов, на которые здесь опирается счёт.
• Kubernetes — вторая половина выката: preStop, startupProbe и readiness, maxSurge и maxUnavailable.
• Планировщик и @Async — группа, которую SIGKILL режет первой, и outbox, который это переживает.
• Идемпотентность при остановке — как получатель отсеивает повторы, когда бюджет не помог.