Вебсокеты жили, но сообщения не доходили: буфер отправки переполнялся молча

MAATRIX

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

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

Сервис — бэкенд уведомлений на Node.js с библиотекой ws, который держит одно вебсокет-соединение на клиента и пушит события: новые сообщения, статусы задач, обновления дашборда. Клиенты — веб-интерфейс и мобильное приложение, часть аудитории сидит на нестабильном мобильном интернете.

Симптом был неровным: у одних пользователей всё работало нормально, у других события переставали приходить через 10–20 минут после подключения. При этом:

• Индикатор соединения на клиенте показывал «онлайн» — потому что клиент честно получал пинги от сервера.
• Сервер не фиксировал close или error для этих сокетов — с точки зрения ws соединение оставалось открытым.
• Перезагрузка страницы (то есть новое TCP-соединение) чинила проблему на время, потом она возвращалась.

Первая реакция дежурного инженера — «клиент врёт о своём статусе» — быстро не подтвердилась: на стороне клиента реально приходили ping-фреймы, JavaScript исправно отвечал pong, всё это было видно в консоли браузера. Значит, транспорт на уровне протокола вебсокета работал. А вот прикладные сообщения — нет.

Что видели в логах и метриках

Стандартный набор дашбордов ничего не показывал: CPU процесса в норме, RSS растёт, но не критично, количество активных соединений стабильное, ошибок 5xx нет (это же не HTTP-запросы, а долгоживущие сокеты). Именно поэтому инцидент не поймал ни один алерт — не было метрики, которая должна была сработать.

Первым сигналом стал ss на самом сервере:

ss -tin state established '( sport = :3000 )' | less

Вывод показывал не только состояние TCP-соединений, но и очереди сокетов. У проблемных клиентов колонка Send-Q (объём данных, ожидающих отправки в сокет ядром) была ненулевой и заметно больше, чем у остальных — там, где у здоровых соединений Send-Q держался около нуля, у зависших клиентов счётчик рос от проверки к проверке.

Дальше добавили точечное логирование внутри приложения — вывели ws.bufferedAmount (свойство самого объекта WebSocket в Node.js, которое показывает, сколько байт поставлено в очередь через send(), но ещё не ушло в сокет) раз в минуту по всем активным соединениям:

setInterval(() => {
  for (const ws of activeConnections) {
    if (ws.bufferedAmount > 0) {
      log.warn('ws backlog', {
        connId: ws.id,
        buffered: ws.bufferedAmount,
      });
    }
  }
}, 60_000);

Картина стала однозначной: у части соединений bufferedAmount не колебался около нуля, а монотонно рос — сотни килобайт, потом мегабайты. Сервер честно вызывал send() на каждое новое событие, библиотека честно клала данные в очередь на отправку, но эта очередь не разгружалась.

Гипотезы, которые отбросили

• Медленная сеть у клиента как единственная причина. Логично было предположить, что дело просто в плохом мобильном интернете — TCP-окно маленькое, данные идут медленно. Это отчасти правда, но не объясняет, почему буфер рос без ограничения, а не просто «отправка идёт медленнее». Плохая сеть — триггер, а не причина поломки.
• Утечка памяти в самой библиотеке ws. Проверили версию, посмотрели список известных issue — ничего похожего под нагрузку конкретно нашего паттерна использования не нашли. Профилирование кучи (--inspect + heap snapshot) показало, что память действительно росла, но именно за счёт буферизованных Buffer-объектов с данными на отправку — то есть это было следствием, а не отдельным багом библиотеки.
• Балансировщик рвёт keepalive и переоткрывает соединения не туда. Проверили логи балансировщика — sticky-сессии по cookie работали корректно, соединение весь инцидент шло на одну и ту же ноду. Эта гипотеза отвалилась быстро, но проверить её всё равно стоило, потому что похожий класс проблем с балансировкой вебсокетов встречается часто.
• GC-паузы приложения. Смотрели метрики event loop lag — были короткие всплески, но не настолько значительные, чтобы объяснить минуты простоя доставки у конкретных клиентов, пока у остальных всё летало нормально.

Отбрасывать гипотезы по одной было не быстро — на каждую уходило по 20–40 минут воспроизведения и проверки, — но именно последовательное исключение довело до реальной причины, а не удача.

В чём была реальная причина

Вебсокет-протокол на уровне контрольных фреймов (ping/pong) и на уровне прикладных данных (data-фреймов) использует одно и то же TCP-соединение, но пинги — это буквально несколько байт. Даже когда буфер отправки сокета переполнен большими data-фреймами, ядро иногда успевает пропихнуть крошечный pong почти сразу, особенно если у него более высокий приоритет по факту меньшего размера и того, что он один. С точки зрения клиента и upstream-мониторинга «пинг-понг» — это и есть индикатор жизни, поэтому соединение выглядело полностью здоровым.

Реальная проблема была в другом: сервер вызывал ws.send(payload) на каждое событие без проверки bufferedAmount и без callback, который бы сообщил, что запись реально ушла в сокет. Node.js ws.send() — асинхронная операция: данные уходят во внутренний буфер и оттуда постепенно пишутся в сокет ядром. Если потребитель (клиент) читает данные медленнее, чем сервер их генерирует — а именно так было с частью мобильных клиентов на нестабильной сети, — буфер начинает расти. Ограничения на размер этого буфера в коде не было, highWaterMark использовался дефолтный, а приложение продолжало ставить в очередь новые события: обновления статуса, уведомления, heartbeat-события бизнес-логики — то есть по несколько сообщений в секунду на активного пользователя.

Итог: за 10–20 минут у клиента с медленным приёмом накапливались мегабайты неотправленных данных. Сокет физически не был мёртв — TCP-соединение существовало, keepalive и ping/pong подтверждали его «живость», — но полезная нагрузка стояла в очереди и практически не продвигалась вперёд, потому что новые события подкладывались быстрее, чем успевали уйти старые. Пользователь получал вебсокет, который выглядел рабочим, но фактически не доставлял ничего актуального — только исторический backlog, который к тому же протухал (пользователю уже не нужны статусы часовой давности).

Отдельно стоит сказать про память: у процесса с тысячами таких соединений незаконтролированный рост буферов на медленных клиентах в сумме давал заметную деградацию RSS процесса, и в худшем случае — риск падения по OOM, если бы инцидент тянулся дольше, а мы не подключились к диагностике.

Как нашли и подтвердили причину на практике

Кроме ss -tin и логирования bufferedAmount, использовали несколько дополнительных проверок, которые стоит держать в арсенале для похожих кейсов:

# сколько байт реально стоит в очереди на отправку у процесса
cat /proc/<pid>/net/tcp | awk '{print $5, $8}'

# то же самое человекочитаемо через ss, с фильтром по порту приложения
ss -tinm state established '( sport = :3000 )'

Поле tx_queue в /proc/<pid>/net/tcp и Send-Q в ss — это, по сути, одно и то же: объём данных, которые ядро уже приняло от процесса, но ещё не смогло протолкнуть в сеть. Если это число растёт и не падает — читатель на другом конце не успевает или перестал читать.

Также воспроизвели проблему искусственно на тестовом стенде: подняли клиента, который подключается к вебсокету и намеренно не читает входящие фреймы (эмуляция «медленного потребителя» — просто не вызывать read()/не обрабатывать событие message), а сервер продолжал слать события с обычной частотой. bufferedAmount на сервере предсказуемо пополз вверх, что подтвердило: механизм воспроизводится детерминированно, а не является случайным совпадением метрик.

Ещё одна полезная деталь: у ws есть встроенный способ узнать реальное состояние сокета на уровне TCP, включая доступ к нижележащему net.Socket (ws._socket во внутренней реализации, в новых версиях — через публичные обёртки) — но полагаться на приватные поля библиотеки в проде не стоит, для диагностики достаточно системных инструментов уровня ОС.

Что изменили после инцидента

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

1. Backpressure-контроль перед отправкой. Перед каждым send() стали проверять bufferedAmount, и если он превышает разумный порог для данного типа соединения — не ставить в очередь очередное событие, а либо схлопывать его с предыдущим (для статусов — отправлять только последнее актуальное состояние), либо явно закрывать соединение с кодом, который клиент понимает как «переподключись».

const MAX_BUFFERED = 1_000_000; // 1 MB, порог — под конкретную нагрузку нужно подбирать отдельно

function safeSend(ws, payload) {
  if (ws.readyState !== ws.OPEN) return;
  if (ws.bufferedAmount > MAX_BUFFERED) {
    ws.close(1011, 'slow consumer');
    return;
  }
  ws.send(payload);
}

1. Схлопывание избыточных обновлений. Часть событий (статусы, счётчики) — это не история, а текущее состояние. Для таких типов сообщений очередь на клиента стали держать в приложении с ключом по типу события, и при отправке брать только последнее значение по каждому ключу, а не накапливать все промежуточные. Это резко снизило объём данных, которые вообще могли встать в очередь у медленного клиента.

1. Явный лимит по времени жизни сообщения (TTL) в очереди. Для событий, которые теряют смысл через какое-то время (уведомления «печатает…», временные статусы), добавили проверку возраста сообщения перед отправкой — если оно устарело, просто не отправлять. Похожий класс проблем — когда сообщения без TTL копятся и съедают ресурсы — подробно разобран в статье про очередь сообщений без TTL: там причина другая (Redis/брокер, а не сокет), но принцип тот же — без явного времени жизни любая очередь рано или поздно станет проблемой.

1. Метрика bufferedAmount в мониторинге. Добавили экспорт этого значения в Prometheus как гистограмму по всем активным соединениям и алерт на долю соединений с ненулевым буфером дольше N минут подряд. Именно отсутствие этой метрики стало причиной, что инцидент не поймали автоматически, а узнали от пользователей.

1. Более жёсткий таймаут неактивности на уровне приложения, отдельный от TCP keepalive — если от клиента давно не было polling-подтверждения о прочтении событий (не просто pong, а прикладной ack), соединение закрывается принудительно, чтобы не копить бесполезный backlog. Смежная история про то, как разница между транспортным keepalive и реальной активностью соединения ломает логику, разобрана в статье про обрывы каждые десять минут.

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

Как теперь читаем такие инциденты быстрее

Главный вывод команды был не техническим, а процессным: стандартный набор дашбордов (CPU, память, количество соединений, HTTP-коды) не покрывает долгоживущие протоколы вроде вебсокетов, где «соединение живо» и «данные доходят» — это два разных утверждения. Поэтому для любого сервиса с постоянными сокетами теперь в чек-лист онбординга добавлен пункт: обязательно завести метрику на буфер/очередь на отправку конкретно для этого протокола, а не полагаться на общие сетевые счётчики.

Общий подход к разбору подобных инцидентов — идти от симптома к логам и метрикам, последовательно исключая гипотезы, а не гадать — описан в статье как читать логи и находить причину сбоя. Тот же принцип сработал и здесь: не пытаться сразу «починить всё», а сузить пространство причин через воспроизводимую диагностику (ss, bufferedAmount, стенд с искусственно медленным клиентом), и только потом писать код.

Частые вопросы