Баги, которые не ловятся тестами: три расследования и общая методика

Есть класс дефектов, которые проходят весь конвейер проверок и всплывают только в продакшене. Объединяет их не сложность кода. В двух случаях виновата форма проверки, написанной вежливой там, где реальность к сервису вежлива не бывает; в третьем проверка не поймала бы дефект вообще.

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

Случай первый: запись, которой не могло не быть

Управляющий слой Tailscale разбит на шарды, у каждого своя база SQLite, и обращается к ней ровно один процесс. Такой однописательный режим — именно то, для чего SQLite и предназначен, что делает дальнейшее особенно неприятным.

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

Первый случай сочли единичным. Базу починили, причину не нашли. Потом это повторилось. И ещё раз. Всего до устранения первопричины набралось 19 отдельных инцидентов за полгода, и каждый означал простой: процесс на шарде останавливался, пока базу чинили или восстанавливали. На ранних инцидентах простой превышал час, и всё это время у клиентов на шарде не работали консоль администратора и API.

Почему он не поддавался обычным приёмам

Дефект сопротивлялся всем стандартным подходам сразу:

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

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

Команда сделала два шага, которые и составляют суть этой истории. Купила контракт поддержки у разработчиков SQLite, получив прямой доступ к людям, написавшим саму базу. И методично составила список гипотез, отсекая их данными, а не рассуждениями. В списке были сломанные блокировки при закрытии файла, неверная работа с памятью, принадлежащей базе, и обращение из нескольких потоков при отключённой потокобезопасности. Каждый инцидент приносил данные, каждая гипотеза отпадала по очереди.

Улика: транзакция, которой не стало

Пока первопричину искали, платформу надо было держать живой. Команда автоматизировала жёсткую остановку при обнаружении повреждения, поставила монитор, непрерывно проверявший целостность резервных копий, и переписала инструкции по восстановлению. Время восстановления упало ниже часа.

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

Конвейер сработал и выдал улику. В двух инцидентах журналы не проигрывались чисто: данные, записанные и зафиксированные одной транзакцией, оказывались необъяснимо невидимы для последующих. Запись исчезла бесследно и без единой ошибки.

Этого не может быть. В сериализуемой однописательной базе зафиксированная запись не может пропасть. Значит, виноват слой с достаточной конкурентностью, чтобы такое спрятать, а такой слой ровно один — контрольные точки.

Шестнадцатилетняя гонка

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

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

Журналы показали редкую гонку данных (race condition) между контрольной точкой и пишущей транзакцией. Если запись происходит в определённый момент работы контрольной точки, та сбивается: считает часть страниц перенесёнными в основной файл, хотя перенос не состоялся. Данные теряются навсегда, а страницы, которые на них ссылаются, например индексные, записываются как ни в чём не бывало. Файл становится структурно повреждённым, что проверка целостности всё это время и фиксировала.

Дефекту дали имя по сбросу журнала предзаписи и оценили его возраст минимум в шестнадцать лет. Он прожил так долго именно из-за редкости, это классический heisenbug: чтобы поймать его в тестовой среде, разработчикам пришлось дописать код, вызывающий гонку намеренно.

Ложная тревога, чуть не сорвавшая исправление

Исправление вышло в версии 3.52.0, и Tailscale раскатывала его осторожно, начав с нескольких канареечных шардов. После общей раскатки монитор резервных копий немедленно покраснел, сообщив о повреждении в тринадцати базах.

Настоящего повреждения не было. В ту же версию попала оптимизация, слегка изменившая округление при переводе текста в число с плавающей точкой, а Tailscale хранила метки времени высокой точности текстом и превращала их в числа в вычисляемом столбце. Индекс по вычисляемому выражению перестал соответствовать новому результату вычисления, и проверка целостности честно назвала это повреждением. Канареечные шарды дефект пропустили просто потому, что на них не оказалось меток времени, попадающих под изменённое округление.

Разбирали это с трёх сторон сразу. Разработчики SQLite отозвали версию целиком и выпустили 3.51.3, содержавшую только исправление гонки. Tailscale перешла на хранение меток времени целыми секундами, поскольку перевод текста в целое число однозначен. А в 3.53.0 появилось автоматическое восстановление таких индексов, чтобы проблема не возникала впредь.

Главный урок этого эпизода:
Канареечная выкатка проверяет только те формы данных, которые в канарейке есть. Если на канареечных узлах нет тех же значений, что в проде, канарейка не подтверждает ничего. Это касается и обновлений самой базы, драйверов и инструментов миграции, а не только кода приложения.

Как доказали, что дефект действительно исправлен

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

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

Случай второй: три процента, терявшиеся только на чистой машине

Второй сюжет проще по масштабу и полезнее в быту. Сервис представлял собой небольшой пересыльщик TCP: принять соединение, читать текстовые строки, передавать дальше. На тестовом стенде входило 97 004 строки, а выходило 94 183. Ни ошибок, ни исключений, просто пропавшие сообщения.

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

Сменить машину раньше, чем код

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

Считать, а не логировать

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

			Отдельный прогон, счётчики по слоям:

отправлено   100 000
разобрано    100 000
отвечено      99 987   <- разрыв здесь
получено      99 987
		

Сервер разобрал всё до последней строки, а ответов отправил меньше, чем разобрал. Это отпечаток пальца конкретного дефекта, и дальше оставалось найти его в коде ответа.

read() ничего не обещает про сообщения

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

			ssize_t r = read(c, buf, sizeof buf);
for (ssize_t i = 0; i < r; ++i)
    if (buf[i] == '\n') parsed++;

write(c, "ok\n", 3);   // один ответ на чтение, а не на строку
replies++;
		

TCP — это поток байтов, а не очередь сообщений. Вызов чтения не имеет понятия о том, что такое одно сообщение в вашем протоколе. Ядро вправе слить десяток сообщений в один сегмент, и одно чтение заберёт все десять, а ответ уйдёт один.

Вежливый локальный тест отправлял сообщение, дожидался подтверждения и отправлял следующее. Одно сообщение на сегмент — дефект спал. Нагрузка на стенде шла пачками, тысячами сообщений в секунду, ядро их группировало, одно чтение проглатывало сотню строк.

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

			std::string acc;
ssize_t r;
while ((r = read(c, buf, sizeof buf)) > 0) {
    acc.append(buf, static_cast<size_t>(r));
    size_t pos;
    while ((pos = acc.find('\n')) != std::string::npos) {
        acc.erase(0, pos + 1);
        parsed++;
        write(c, "ok\n", 3);   // ответ на каждую строку, а не на чтение
    }
}
		

Вывод автора расследования:
Локальный тест это не нагрузочный тест, ноутбук это не сервер, а одно чтение из сокета это не одно сообщение.

Третий сюжет: гонки, которые видит только поддержка

Третий сюжет про биллинг кредитов на бессерверном Postgres, где транзакции по условиям задачи были недоступны. Автор наткнулся на четыре гонки, разберём две самые показательные. Все они, по его собственной формулировке, относятся к тому сорту дефектов, которые не показываются в тестах и показываются в почте поддержки.

Классический двойной расход

Наивная версия, которую пишут первой:

			const balance = await getBalance(userId);
if (balance < cost) throw new Error("Недостаточно кредитов");
await setBalance(userId, balance - cost);
		

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

Инвариант переезжает в условие запроса

Общее решение — сделать проверку и запись одним оператором, перенеся условие корректности в WHERE:

			UPDATE credits_balance
SET balance = balance - $amount
WHERE user_id = $userId AND balance >= $amount
RETURNING balance;
		

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

Вебхук, доставленный дважды

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

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

			WITH gate AS (
  INSERT INTO credits_transactions (user_id, delta, type, ref_id)
  SELECT $userId, $amount, 'pack_purchase', $refId
  ON CONFLICT (ref_id) WHERE type IN ('plan_grant', 'pack_purchase')
  DO NOTHING
  RETURNING id
)
INSERT INTO credits_balance (user_id, topup_balance)
SELECT $userId, $amount WHERE EXISTS (SELECT 1 FROM gate)
ON CONFLICT (user_id) DO UPDATE
  SET topup_balance = credits_balance.topup_balance + EXCLUDED.topup_balance;

-- ворота держатся на частичном уникальном индексе
CREATE UNIQUE INDEX credits_tx_grant_idem_idx
  ON credits_transactions (ref_id)
  WHERE type IN ('plan_grant', 'pack_purchase');
		

Деталь, которую стоит забрать отдельно: уникальный индекс под эту схему должен быть частичным. Начисления от администратора приходят с произвольным идентификатором из скрипта, и глобальный уникальный индекс рисковал бы столкнуть их друг с другом или с идентификатором операции другого типа. Приветственные начисления идут вообще без идентификатора, и с ними коллизии не будет в любом случае: Postgres не считает два пустых значения равными. Ограничение индекса двумя типами операций от платёжного провайдера держит проверку уникальности ровно там, где она нужна.

Что из этого складывается

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

Что забрать с собой

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

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

Полезнее всего здесь дешёвые привычки. Счётчик на границе каждого слоя ставится за час. Пачечный клиент пишется за вечер. Датчик, доказывающий исправление положительным сигналом, добавляется одной строкой в драйвер. Всё это стоит несопоставимо меньше, чем полгода расследования.

Три постмортема, на которых строится разбор: разбор Tailscale о поиске шестнадцатилетнего бага в SQLite, ретроспектива потери трёх процентов сообщений и четыре гонки в биллинге на бессерверном Postgres.

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