Мой мониторинг аптайма сам нагенерил 932 фантомных падения

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

2 июня, 07:28 UTC. У меня сервис мониторинга аптайма: тысяча с лишним чужих сайтов, которые он проверяет каждую минуту и шлёт владельцу алерт, если что-то упало. И вот в 07:28 он начинает рассылать алерты о том, что упало примерно всё. RustFS лежит. Мониторинг ИБП лежит. Telegram-боты лежат. Всё разом красное. За 25 минут система открыла 932 инцидента.

Сайты были живы. Все до единого.

Я был уверен, что поймал утечку дескрипторов. Оказалось, дело в одной ненастроенной строке конфига и в оптимизации, которая работала наизнанку. Самое обидное тут даже не ложная тревога. Обидно, что сервис, вся работа которого отличать «упало» от «не упало», сам устроил себе ложный обвал на весь дашборд — 932 несуществующих падения за 25 минут.

TL;DR

• В 07:28 UTC бэкенд начал ловить OSError: [Errno 24] Too many open files — 4488 раз за 12 часов. Проверки посыпались на всех протоколах сразу, мониторы поехали в ложный DOWN.

• Soft-лимит nofile в контейнере был 1024 (systemd-дефолт 1024:524288, унаследованный контейнером; в compose.yaml его не выставляли). Hard при этом 524288, поднимать было нечего.

• Дескрипторы жрала не классическая утечка. 60 воркеров-корутин держали каждый свой httpx-пул, на лидере набегало под 120 пулов и 468 простаивающих keepalive-соединений, причём один и тот же адрес повторялся до 15 раз.

• Чинил в два захода: сначала поднял лимит до 65536 и пересоздал контейнер, потом сделал один общий пул на процесс вместо 120. И повесил алерт на process_open_fds / process_max_fds, чтобы в следующий раз узнать заранее.

Что вообще за сервис

Без контекста дальше никак. Бэкенд на FastAPI 0.136, крутится под uvicorn 0.41 в Docker на одной VM в Yandex Cloud под Ubuntu 24.04. Внутри живёт фоновый цикл проверок: пул из 60 воркеров (worker_count = 60, дефолт в конфиге) разбирает задачи из Redis-очереди и долбит health-чеки по чужим хостам. HTTP, TCP, ICMP, DNS, SSL, всё подряд. На момент инцидента активных HTTPS-мониторов было 1187.

Важная деталь: это не 60 процессов и не 60 потоков, а 60 asyncio-корутин в одном event loop процесса-лидера. Каждая в цикле берёт задачу из Redis и await-ит health-check. Все их пулы соединений живут в одном адресном пространстве и делят один лимит дескрипторов.

Ещё один нюанс, который выстрелит позже. В проде два uvicorn-процесса, но 60-корутинный пул проверок запускается только на одном из них, на том, кто выиграл выборы лидера через Redis-лок. Второй процесс обслуживает только входящий API. Запомните это, пригодится.

Первая версия, и почему она была неправильной

Лезу в логи. Их заливает вот этим:

OSError: [Errno 24] Too many open filesICMP check failed: [Errno 24] ... can't spawn subprocesscannot open /etc/resolv.conf: Too many open files

Первая мысль очевидная: ICMP отвалился, DNS не резолвится, значит проблема в сети или в подсистеме пинга. Полчаса я смотрел не туда.

Потом дошло. ICMP, resolv.conf и subprocess тут жертвы. Когда у процесса кончились дескрипторы, он физически не может ни сокет открыть, ни файл /etc/resolv.conf прочитать, ни subprocess для пинга породить. Errno 24 был один на всех. Лог показывал последствия в порядке живой очереди, а корень был общий: в контейнере кончились file descriptors. Это и есть классический EMFILE, «too many open files». POSIX стандартизирует имя ошибки и её смысл (процессу не дают открыть ещё один дескриптор сверх его лимита RLIMIT_NOFILE), а номер errno 24 это уже деталь Linux-ABI. Кстати, не путать с ENFILE: тот прилетает, когда дескрипторы кончились во всём ядре (/proc/sys/fs/file-max), а у меня упёрся лимит одного процесса.

Где именно кончились

Дальше уже по приборам. Беру PID бэкенда, смотрю лимиты:

PID=$(docker inspect -f '{{.State.Pid}}' pinger-backend)cat /proc/$PID/limits | grep 'open files'# Max open files   1024   524288   files

Soft 1024, hard 524288. То есть потолок, в который я упёрся, поднимается одной строчкой, и места до настоящего предела вагон. Просто soft-лимит остался дефолтным, потому что секции ulimits в compose.yaml не было вообще, с самого начала, и никому не мешало.

Уточню сразу, пока не набежали в комментарии: 1024 — не вечный «дефолт Docker». Это пара 1024:524288 из systemd (DefaultLimitNOFILE), которую контейнер унаследовал. На Docker Engine 20.10–28 контейнер нередко получал и 1048576, а жёстко 1024 вернулось дефолтом только в Engine 29 (containerd 2.1.5). Число зависит от версии и хоста, так что проверьте именно своё.

Считаю дескрипторы у воркеров:

ls /proc/<worker-pid>/fd | wc -l

Старый процесс-лидер, проживший 11 часов, сидел ровно на 1024. Молодой, которому было 19 минут, на 52. Растёт со временем, упирается в стенку, начинает сыпаться. Разбивка по типам через ls -l /proc/<pid>/fd дала картину: 592 сокета (из них 41 в CLOSE_WAIT на :443 и :80, потому что апстрим закрыл соединение по своему keepalive-таймауту раньше моего 60-секундного, и httpx дочистит такой сокет лениво, при следующем обращении к пулу) плюс 407 штук /dev/null.

Сразу оговорюсь про эти 407 /dev/null, потому что глаз за них цепляется: это следствие уже наступившего EMFILE, а не причина. На здоровом процессе их три-четыре; распухают они только когда дескрипторы кончились и часть ресурсов не доинициализировалась как надо. Главный потребитель всё-таки сокеты.

И тут вторая ловушка. --limit-max-requests перезапускает весь uvicorn-процесс после N входящих HTTP-запросов. Но фоновый пул из 60 корутин живёт внутри процесса-лидера, а входящий трафик почти весь забирает второй процесс, и счётчик запросов на лидере почти не растёт. Значит процесс с фоновым циклом не перезапускается, и дескрипторы растут монотонно, без сброса, пока не упрутся в 1024.

Казалось бы, вот и ответ: подними лимит и живи. Поднял. Но мне не давал покоя вопрос, на который «подними лимит» не отвечает. А почему, собственно, легитимному процессу нужно под тысячу дескрипторов на ровном месте?

Настоящая причина: оптимизация, размноженная в 60 раз

Вот тут начинается интересное.

Каждый из 60 воркеров в конструкторе создавал свою собственную HealthCheckerFactory. Фабрика по задумке кэширует чекер на каждый протокол, чтобы переиспользовать соединения, нормальная оптимизация. Внутри HTTP-чекера живут два httpx-клиента (один проверяет TLS-сертификаты, второй нет), и у каждого свой пул: max_connections = 200, max_keepalive_connections = 50, keepalive_expiry = 60s.

Теперь арифметика. Фабрика-то на каждый воркер своя. Значит на процессе-лидере, где крутятся все 60 воркеров, живёт как минимум 60 × 2 = 120 независимых httpx-пулов: у каждого воркера свой HTTP-чекер с двумя клиентами, с проверкой TLS и без. Если воркер успел закэшировать и http, и https (это разные ключи в кэше фабрики), пулов на него вдвое больше. Оптимизация, которая должна была переиспользовать соединения, схлопнулась наизнанку: каждый из 60 воркеров независимо держит собственный keepalive к популярным хостам.

Считаем сокеты

Чтобы не гадать, замерил живьём:

Разница в 10 раз, и вся она в этих пулах. Уточню про числа, чтобы не путать: 815 — это снимок лидера в относительно спокойный момент, а та самая «ровно 1024» из прошлого раздела — снимок на пике, под нагрузкой плато подходило к лимиту вплотную, там и начинался EMFILE.

Дальше разложил установленные веб-соединения на лидере по состоянию через ss:

nsenter -t $PID -n ss -tan | awk '{print $1}' | sort | uniq -c

Из примерно 470 соединений в состоянии ESTAB активными были два. Два. Остальные 468 простаивали в keepalive. То есть 99.6% соединений просто висели и ничего не делали. При этом на 470 коннектов приходилось всего 244 различных IP: один и тот же адрес повторялся до 15 раз, потому что каждый воркер независимо держал собственное соединение к, скажем, github.com.

Плато под 800 дескрипторов оказалось не нагрузкой. Это 120 несшаренных пулов, надышавших гору одинаковых простаивающих keepalive-соединений. Реальная конкурентная работа в этот момент занимала два сокета.

Чтобы баланс сходился: дескрипторы лидера складываются из трёх кусков: около 554 веб-сокетов (из них 468 простаивающий keepalive), 107 коннектов к Redis и остаток на пайпы и /dev/null. Не пытайтесь свести одни keepalive со стенкой 1024, картина набирается из всех трёх.

Тот же веер тремя днями раньше

Кстати, это был не первый звоночек. 30 мая этот же 60-кратный веер высадил пул соединений к PostgreSQL: 60 воркеров разом лезли в базу и выбирали пул подчистую. Прикрыл семафором на 40 одновременных запросов (worker_db_max_concurrency = 40, инициализируется в core/lifespan.py). Болячку нашёл, диагноз поставил, но почему-то решил, что она только про базу. Что ровно тот же веер раздувает и httpx-пулы, и заодно упирается в nofile, мысль я не продлил. Классика: залатал симптом там, где он первый раз стрельнул, и не пошёл смотреть, где он стрельнёт следующим.

Как чинил

В две стадии. Хронология такая:

Немедленно поднял soft-лимит и пересоздал контейнер:

ulimits:  nofile:    soft: 65536    hard: 65536

Важная деталь, на которой легко обжечься: docker compose restart ulimit-ы не применяет. ulimits это поле OCI runtime-спеки (process.rlimits), и runc выставляет его при СОЗДАНИИ контейнера, а не при старте. Нужен именно up -d с пересозданием, иначе вы рестартнёте процесс под тем же старым лимитом и будете гадать, почему ничего не поменялось.

Кстати, если трогать compose не хочется, есть второй путь: непривилегированный процесс может сам поднять soft-лимит вплоть до hard без root и без CAP_SYS_RESOURCE. Вызвать resource.setrlimit(RLIMIT_NOFILE, (hard, hard)) на старте приложения или ulimit -n в энтрипоинте. Hard у меня уже был 524288, так что запас был и без пересоздания.

По-нормальному убрал саму причину размножения. Теперь WorkerPool создаёт одну HealthCheckerFactory на процесс, поднимает её один раз и прокидывает в каждый воркер параметром. Воркер закрывает фабрику только если создал её сам (флаг _owns_checker_factory, чтобы автономный и тестовый пути не сломались). 120 пулов схлопнулись в одну пару на процесс.

По прикидке 244 хоста, упёртые в max_keepalive_connections = 50, дают вместо 468 простаивающих соединений где-то 50–100, в 5 раз меньше. Сразу честно: это расчётная оценка, а не замер. Общий factory выкатывался отдельно, и графика FD строго после него у меня под рукой нет, поэтому привожу цифру как прогноз, а не как факт. Сверху повесил регрессионный тест, чтобы кто-нибудь снова не развёл фабрику по воркерам.

Что с ложными инцидентами

За окно 07:28–07:53 система открыла 932 инцидента. Когда дескрипторы освободились, 915 из них (это 98%) авторезолвнулись сами: чек снова прошёл, инцидент закрылся. Осталось 17 открытых, примерно 2% от шторма, и все 17 оказались настоящими, на реально лежавших мониторах. Стейт-машина инцидентов отработала массовый ложный флип ровно как задумано, руками разгребать переоткрытые инциденты не пришлось.

Дальше смешное. Алертов за всё окно ушло около 19. Девятнадцать, на 932 инцидента. Точную раскладку по причинам я не сводил, но главный фактор очевиден: доставка алертов сама сидела на тех же дохлых дескрипторах и физически не могла отправить большую часть. Сверху, вероятно, наложились кулдаун и circuit breaker. То есть пользователей от шторма ложных уведомлений спасла, по сути, та же поломка: побочный эффект отказа, а не моя предусмотрительность.

Тут важно не запутаться в числах, иначе кажется, что они не сходятся. Авторезолв закрыл инциденты как состояние, но не стёр их из истории клиента: в таймлайне монитора остался фантомный провал. Поэтому отдельно, уже по факту, я вычистил из истории 790 закрытых записей с однозначной EMFILE-сигнатурой (too many open files, errno 24, cannot open /etc/resolv.conf) одним транзакционным DELETE. Это подмножество тех 915 авторезолвнутых, а не что-то сверх 932. Оставшиеся в окне ~125 трогать не стал: там вперемешку таймауты и connection failed, которые при тогдашнем базовом фоне в 62 инцидента в час вполне могли быть настоящими. Плюс 17 по-прежнему открытых — тоже настоящие. Лучше недочистить, чем затереть реальное падение из истории клиента.

Что из этого стоит унести с собой

Первое и самое прозаичное. Soft-лимит nofile, который контейнер наследует, зависит от того, как настроены демон и хост, и в моей инсталляции это были дефолтные 1024, цифра из той эпохи, когда тысяча сокетов была экзотикой: она тянется от FD_SETSIZE = 1024 в glibc, select() физически не следит за дескрипторами с номером ≥ 1024, и man select(2) прямо зовёт это «unreasonably low limit for many modern applications». Для любого Python-сервиса, который держит пулы соединений под высокой конкурентностью, это мина. Проблема даже не в аппетите. Лимит низкий, а расход растёт тихо. Проверьте свой прод прямо сейчас, одной командой:

cat /proc/$(docker inspect -f '{{.State.Pid}}' <container>)/limits \  | grep 'open files'

Если там 1024 и у вас внутри httpx, aiohttp, asyncpg или любой другой пул, вы просто ещё не дорастили нагрузку до стенки.

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

Третье. Чините класс бага. У меня тот же 60-кратный веер за три дня до этого положил пул к базе, я прикрыл базу и на том успокоился. httpx-пулы и nofile остались с той же болячкой и подождали своей очереди 72 часа. Когда чините ресурсную проблему, спросите себя, где ещё в системе живёт тот же паттерн.

Четвёртое. Кто мониторит мониторинг. У сервиса, который меряет чужой аптайм, не было алерта на собственный расход дескрипторов. Теперь есть: Prometheus отдаёт process_open_fds и process_max_fds, отношение первого ко второму выше 0.7 — повод проснуться.

Нюанс: под --workers в multiprocess-режиме prometheus_client эти дефолтные метрики не агрегирует, так что пришлось завести свой gauge, который раз в 15 секунд пишет len(/proc/self/fd) и getrlimit(RLIMIT_NOFILE). Порог взят 0.7, а не 0.9, потому что рост у меня монотонный и медленный, на часы, а не спайковый: на 0.7 ещё остаётся запас в несколько часов до стенки, этого хватает на ручную реакцию. Для спайковых нагрузок порог имеет смысл опускать. Дешёвая метрика, которая превратила бы тот инцидент из «25 минут шторма и ручной разбор» в «тикет за неделю до».

Почему это так легко повторить

Самое неприятное даже не баг, а то, насколько он типовой. Секции ulimits в большинстве примеров compose.yaml просто нет — у автора примера до стенки не дорастало, и проблема копируется вместе с конфигом. А worker_count крутят как ручку громкости, и каждый щелчок молча умножает то, что внутри воркера выглядело невинной оптимизацией. Число воркеров касается не только CPU. Это ещё и про то, сколько копий ваших пулов, клиентов и буферов вы только что создали.

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

Весь этот разбор был на моём проде, pingzen.dev, уптайм-мониторинг. Никакой морали про «у нас бы такого не случилось» не будет: как видите, случилось, я об этом и пишу.

Вопрос к залу

У кого ловили EMFILE из-за дефолтных лимитов контейнера, а не из-за настоящей утечки? И чем мониторите расход дескрипторов и сокетов в проде, кроме как «упало, пошли смотреть»? Поделитесь в комментариях: на каком отношении open_fds / nofile будили бы вы дежурного? У вас 0.7 — это много или мало?