Мой сервер врал «готово» каждому новичку

Новичок открывает первый кейс, о котором я рассказывал в первой статье., читает брифинг, и через пять секунд сайт пишет: «Готово, жми „Начать“». Он жмёт и смотрит на пустое окно терминала. Секунд через десять там ошибка, страница сама перезагружает терминал, и только потом появляется консоль.

Сервер при этом не падал, CPU и память в норме, алерты молчат. Были только строчки в журнале, которые я чуть не записал в «обычный шум».

180 строк, которые я чуть не записал в шум

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

Почти все были одной и той же: Terminal container did not become ready. Около 180 строк с последнего перезапуска сайта, плюс 16 падений WebSocket-прокси терминала. Первая мысль — шум: игрок закрыл вкладку, окружение убрали, прокси не достучался. Я так и внёс их в исключения алертов.

Потом открыл код прокси. Сайт проксирует терминал ttyd из контейнера игрока и, если контейнер только что стартовал, ждёт его до 10 секунд:

def _fetch_upstream(url):    """GET к ttyd; контейнер мог только что стартовать — ждём до 10 с."""    deadline = time.monotonic() + 10    while True:        try:            return requests.get(url, timeout=(0.5, 15), ...)        except requests.ConnectionError as error:            if time.monotonic() >= deadline:                log.error("Terminal container did not become ready at %s: %s", url, error)                abort(502, description="Не удалось подключиться к консоли сценария.")            time.sleep(0.25)

До этого места запрос доходит, только если контейнер жив. Для удалённого контейнера игрок сразу получает «Сессия истекла», и в журнал ничего не пишется. Значит, каждая строка — живой контейнер, в котором терминал 10 секунд не отвечал. Это не шум.

И ещё деталь: 113 из ~180 строк — у гостей. А гостям без регистрации доступен только кейс 0.

Замер: когда терминал на самом деле готов

Чтобы не гадать, я замерил это напрямую. Скрипт внутри веб-контейнера запускал окружение той же функцией, что и сайт, и каждые 100 мс пробовал подключиться к порту ttyd.

[embed: node/c28cc3ae-b3f5]

В остальных кейсах терминал готов задолго до «Готово». В кейсе 0 он отвечает на 7,8 секунды позже, а прокси ждёт всего 10 секунд с момента «Начать». Кто жмёт сразу, укладывается впритык, а на загруженном сервере уже нет.

Почему именно кейс 0

Кейс 0 — обучение: ночная задача съела процессор, выгрузка забила диск, сервис упал. Всю поломку готовит entrypoint контейнера, а терминал запускается последней строкой:

sudo python3 /usr/local/lib/scenario/seed_uploads.py         # файлы магазинаsudo -u jobs dd if=/dev/zero of="/var/lib/shop/$FILE" bs=1M  # выгрузка забила разделsudo -u jobs nohup python3 "/opt/jobs/$JOB.py" &            # зависшая задача: 100% CPUsudo pd-systemd-boot                                         # «загрузка» сервисовexec /usr/local/bin/start-terminal.sh                        # ttyd

Контейнеру этого кейса разрешена четверть ядра (cpu_quota=25000 при периоде 100000). Накануне я урезал её с половины: дашборд считает CPU от лимита, и зависшая задача всё равно видна на 100%, а на сервер помещается больше игроков. Но задача стартует до «загрузки» сервисов и сразу съедает эту четверть: Python-скрипты подготовки и сам ttyd стоят к процессору в очереди за ней.

Для сравнения: в кейсе 2 тот же лимит и тоже нарочная нагрузка на CPU, а терминал готов через 0,9 с. Дело не в лимите как таковом, а в том, сколько работы стоит перед ttyd и с кем она делит четверть ядра.

А сайт считал готовность так: контейнер стартовал — значит, через warmup_seconds инцидент готов. У кейса 0 это 5 секунд:

now = time.time()# Инцидент развивается warmup_seconds, пока игрок читает брифинг.attached = database.attach_container(    run_id, info["container_id"], info["host"],    now + SCENARIOS[scenario_id]["warmup_seconds"],)

Выдержка задумывалась как время, пока сервер «успевает сломаться», а игрок читает брифинг. А стала обещанием, которое никто не проверял. Дальше срабатывала страховка на странице: если в окне терминала ошибка, она перезагружает его каждые 3 секунды. Поэтому в итоге всё «работало», просто первые 10–20 секунд выглядело сломанным.

Таймер — не проверка готовности

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

• sleep 10 в скрипте деплоя перед миграциями или smoke-тестом;

• depends_on в docker compose без condition: service_healthy: compose ждёт только запуска контейнера, а не готовности сервиса в нём;

• pod в Kubernetes без readinessProbe получает трафик, как только стартовал контейнер; initialDelaySecondsу пробы — тот же таймер;

• юнит systemd с Type=simple считается запущенным сразу после старта процесса, и After= у соседних юнитов ждёт именно этого, а не готовности.

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

И ломается таймер не громко. Никакого падения, только редкие 502 и перезапуски, которые все привыкли считать шумом.

Исправление: ждать то, что увидит игрок

Правило простое: «готово» — только после проверки того, чем будет пользоваться человек. Для терминала это порт ttyd: принял подключение — можно звать игрока.

TERMINAL_READY_TIMEOUT_SECONDS = 30def wait_for_terminal(host, timeout=TERMINAL_READY_TIMEOUT_SECONDS):    """Дождаться, пока ttyd в контейнере примет подключение; False — не дождались."""    deadline = time.monotonic() + timeout    while True:        try:            socket.create_connection((host, TERMINAL_PORT), timeout=1).close()            return True        except OSError:            if time.monotonic() >= deadline:                return False            time.sleep(0.2)

При запуске окружения контейнер теперь привязывается к игроку только после этой проверки. До неё игрок видит «Поднимаем окружение…», а не «Готово»:

if not containers.wait_for_terminal(info["host"]):    log.warning("Terminal of %s did not answer in %d s; letting the player in anyway", ...)now = time.time()# Инцидент развивается warmup_seconds; ожидание терминала входит в это время.attached = database.attach_container(    run_id, info["container_id"], info["host"],    max(now, info["started_at"] + SCENARIOS[scenario_id]["warmup_seconds"]),)

Три решения в этих строках:

1. Выдержка считается от старта контейнера и включает ожидание. Быстрые кейсы не ждут дольше прежнего, медленные не ждут дважды.

2. У ожидания есть потолок — 30 секунд. Если терминал так и не ответил, игрока всё равно пускают, а в журнал уходит предупреждение. Медленная консоль лучше вечного экрана загрузки.

3. Проверка — TCP-подключение к порту, а не HTTP-запрос. ttyd открывает порт, когда уже готов отдавать страницу, и проверка стоит миллисекунды. Для сервиса с базой и кэшами порта было бы мало — там нужен настоящий запрос.

Отдельно починил сам кейс 0: зависшая задача теперь запускается последней, рядом с терминалом. Подготовка больше не делит с ней четверть ядра, а для игрока ничего не меняется: к началу инцидента она уже первая в top.

sudo pd-systemd-boot                                         # сервисы — сначалаsudo -u jobs nohup python3 "/opt/jobs/$JOB.py" &            # нагрузка — последнейexec /usr/local/bin/start-terminal.sh

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

Что получилось

Теперь к моменту «Готово» терминал уже отвечает, и первый запрос к нему идёт сотые доли секунды вместо 8–9. Замеры на тестовой машине, кейс 0, по несколько запусков на каждую строку:

Перестановка нагрузки дала примерно 5 секунд. Остальные 7 — сама подготовка в четверти ядра, и они всё ещё дольше пятисекундной выдержки. Поэтому настоящее исправление — проверка, а перестановка лишь сокращает ожидание: таймер в 5 секунд врал бы и после неё.

На тестовой машине рядом никто не играет, и первый запрос там ещё укладывался в 10 секунд прокси. На проде, где процессор делят живые игроки, судя по журналу, уже регулярно нет.

Открытый вопрос: сколько таких ошибок на проде за первые сутки после выкатки (до неё — около 9 в час).

Чек-лист: как не врать «готово»

• Найдите все места, где «готово» означает «прошло N секунд»: sleep, initialDelaySeconds, выдержки в коде.

• Проверяйте то, чем пользуется человек или следующий сервис: порт, HTTP-ответ, тестовый запрос. «Контейнер запущен» — не проверка.

• Дайте ожиданию потолок и заранее решите, что делать, если не дождались: пустить с предупреждением или честно показать ошибку.

• Мерьте время старта с настоящими лимитами CPU и памяти. И заново — после каждой правки лимитов.

• Перечитайте ошибки, которые привыкли считать шумом. Для каждой ответьте: при каком условии код вообще доходит до этой строки?

docker compose: depends_on с условием и healthcheck у того, кого ждут.

services:  api:    healthcheck:      test: ["CMD", "curl", "-fsS", "http://localhost:8080/health"]      interval: 2s      timeout: 2s      retries: 30  worker:    depends_on:      api:        condition: service_healthy

Kubernetes: startupProbe для медленного старта вместо initialDelaySeconds, readinessProbe — чтобы трафик шёл только в готовый pod.

startupProbe:              # до 60 × 2 с на старт; liveness пока не трогает  httpGet: {path: /health, port: 8080}  periodSeconds: 2  failureThreshold: 60readinessProbe:            # трафик — только когда отвечает  httpGet: {path: /ready, port: 8080}  periodSeconds: 5

systemd: Type=notify, если сервис умеет сказать READY=1; иначе — ожидание в ExecStartPost, чтобы юниты с After= стартовали после настоящей готовности.

[Service]ExecStart=/usr/local/bin/apiExecStartPost=/usr/bin/timeout 30 sh -c 'until curl -fsS http://localhost:8080/health; do sleep 0.5; done'

Скрипт деплоя: цикл с потолком вместо sleep 10.

timeout 30 sh -c 'until curl -fsS http://localhost:8080/health >/dev/null; do sleep 0.5; done' \  || { echo "api не поднялся за 30 с" >&2; exit 1; }

Вместо вывода

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

А какую ошибку из «обычного шума» вы последний раз приняли всерьёз? Пишите в комментариях.