38 тысяч зомби: как восьмисекундный таймаут выключил отключение должников

В субботу вечером мы разбирали логи рабочего сервера — рутинная проверка, искали ошибки 500. Их почти не нашлось: три за неделю, и две уже были исправлены. Зато нашлась другая строка. Она повторялась ровно 140 раз в час, со вчерашнего обеда и до этой минуты:

disconnect_user failed: can't start new thread

Это была часть биллинга, которая отключает заблокированных абонентов. Полтора дня она не работала, а в логе рядом с каждой ошибкой стояло «disconnect: OK».

Что сломалось

Когда баланс абонента уходит в минус, биллинг ставит блокировку. Если человек в этот момент в сети, оборудование продолжает присылать отчёты о его сессии. Биллинг замечает «заблокирован, но онлайн» и разрывает сессию: отправляет RADIUS-команду на все NAS параллельно, а на MikroTik дополнительно заходит по SSH.

Этим занимается отдельный фоновый воркер, чтобы массовая блокировка должников в начале месяца не тормозила остальные задачи. Именно он с пятницы не мог запустить ни поток, ни процесс. Больше сотни заблокированных абонентов оставались в сети.

Сначала — команда, которая показывает баг

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

Зайти внутрь контейнера воркера не получилось: даже docker exec падал с ошибкой запуска процесса. Пришлось смотреть снаружи, с хоста. У каждого контейнера есть счётчик задач и лимит:

pids.current = 38458
pids.max     = 38460

Лимит занят полностью. При этом процессов в контейнере числилось всего пять. Так бывает в одном случае: задачи уже завершились, но их никто не подобрал. Это зомби-процессы, и в контейнере их было 38 453. Все — ssh, у всех один родитель: главный процесс воркера.

Откуда зомби

Завершившийся процесс в Linux не исчезает сразу. Он остаётся в таблице процессов, пока родитель не прочитает код его завершения. Обычно это занимает миллисекунды.

Чтобы выполнить команду на MikroTik, воркер запускал sshpass, а тот — ssh. Команда ограничена восемью секундами. Если NAS принял соединение, но завис, срабатывает таймаут, и Python убивает процесс, который запускал сам, — sshpass. Про внука он не знает. ssh остаётся без родителя.

Осиротевший процесс в Linux переходит к PID 1. На обычном сервере это systemd или init, и они подбирают сирот. Но в Docker-контейнере PID 1 — это то, что в нём запустили. У нас это был сам воркер, а он чужих детей не ждёт. Каждый таймаут оставлял один зомби навсегда.

flowchart TD
  A[NAS принял соединение и молчит] --> B[Таймаут 8 с:<br/>Python убивает sshpass]
  B --> C[ssh остаётся без родителя]
  C --> D[Его подбирает PID 1 —<br/>воркер, который детей не ждёт]
  D --> E[Зомби навсегда,<br/>~280 в час]
  E --> F[Лимит 38 460 задач исчерпан:<br/>отключения не запускаются]

Дальше арифметика. Два NAS за медленным каналом давали около 280 таймаутов в час. Лимит задач на контейнер — 38 460 (systemd по умолчанию выдаёт 15% от системного максимума). Контейнер стартовал 5 сентября и упёрся в потолок через 5,6 суток.

Проверили напрямую: разложили время рождения зомби и время таймаутов по часам. За 135 часов вышло 38 375 зомби на 40 017 таймаутов, корреляция — 1,000. Успешные вызовы зомби не оставляют, только таймауты.

Почему в логе было «OK»

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

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

Как чинили

Сразу — перезапуск воркера. Вместе со старым PID 1 исчезают и все его зомби. Через минуту отключения снова пошли. Но утечка никуда не делась: через пять суток всё бы повторилось, и проверка это показала — пять новых зомби в первую же минуту.

Потом — код. Новая функция запуска команд по таймауту убивает не процесс, а дерево процессов, причём снизу вверх: сначала листья, и ждёт, пока живой родитель их подберёт. Первая версия убивала ssh и sshpass одновременно. sshpass не успевал подобрать ssh, и тот снова уходил зомби к PID 1. Эту гонку поймал тест.

Тест, который воспроизводит прод. Настоящие sshpass и ssh подключаются к порту, который принимает соединение и молчит, как зависший NAS. Запускается в одноразовом контейнере из того же образа, где Python стоит PID 1. На старом коде тест красный, на новом — зелёный. После выкладки за первые восемь минут случилось 47 таймаутов — и ни одного зомби.

И последний шаг — init в контейнерах. Параметр init: true в docker-compose ставит в PID 1 маленький tini, который подбирает любых сирот, откуда бы они ни взялись. Это закрывает весь класс ошибок, а не только наш случай.

Что проверить у себя

Если у вас в Docker работают фоновые задачи, которые запускают внешние команды, — это пять минут:

• Кто PID 1 в контейнере. docker inspect -f '{{.HostConfig.Init}}' <контейнер>. Если пусто, а внутри Celery, gunicorn или ваш скрипт — добавьте init: true.
• Сколько зомби. ps -eo stat | grep -c Z. Больше десятка и растёт — утечка.
• Смотрите на лимит, а не на процессы. Зомби не видны в списке процессов контейнера, но занимают pids.current в его cgroup.
• Таймаут убивает только прямого потомка. Особенно опасны обёртки: sshpass, sh -c, expect.
• Не возвращайте «пусто» при ошибке. Сбой, похожий на успех, живёт дольше любого другого.

Как это работает в СмИТ Биллинге

Блокировка по балансу ставится автоматически, а разрыв сессии идёт двумя путями сразу: RADIUS-команда на все NAS параллельно и SSH-команда на MikroTik. Отключения обслуживает отдельная очередь, поэтому массовая блокировка первого числа не задерживает остальные фоновые задачи.

Для оборудования за медленным каналом в карточке NAS есть свой таймаут SSH и выключатель разрыва сессий. На странице «Состояние NAS» видно, какое устройство не отвечает и сколько абонентов это затрагивает.

После этого разбора таймаут больше не оставляет процессов, а в журнале видно, какой NAS и за сколько секунд не ответил, — вместо «OK».