В конце прошлого года с доступностью нашего сервиса всё было довольно плохо. Это хорошо видно на странице статуса, и нестабильность продолжилась уже в новом году. Причиной многих сбоев оказался один-единственный баг глубоко внутри SQLite. На его поиски ушли месяцы напряжённого расследования.
Сейчас уже лето прошло, и мы уверены, что нашли этот баг, разобрались, как он работает, а главное – исправили его.
Мы понимаем, что пользователи ждут от Tailscale надёжной работы, и несколько месяцев мы этим ожиданиям не соответствовали. Мы написали эту статью, чтобы рассказать, что пошло не так, как мы действовали и как в итоге помогли обнаружить давний баг в самом сердце SQLite.
TL;DR:
За шесть месяцев Tailscale столкнулась с 19 случаями повреждения SQLite и длительными простоями отдельных шардов. Причину удалось найти только после внедрения журналирования транзакций и специального диагностического слоя tmstmpvfs: редкая гонка между записью и созданием контрольной точки заставляла SQLite считать, что страницы уже перенесены из WAL в основной файл. В результате часть данных терялась, а база повреждалась без явной ошибки.
Баг существовал минимум 16 лет и чаще проявлялся у Tailscale из-за ручного запуска контрольных точек с высокой частотой. Исправление вошло в SQLite 3.51.3; первоначальный релиз 3.52.0 пришлось отозвать из-за другой проблемы с индексами по выражению. Это подробный разбор расследования, в котором надёжная технология дала сбой при редком, официально поддерживаемом сценарии использования.
Для клиентов наш управляющий контур выглядит как единая публичная точка входа – controlplane.tailscale.com. Но внутри он разделён на несколько серверов координации, или «шардов». В каждый момент времени каждый tailnet находится на одном внутреннем шарде, но при необходимости может незаметно мигрировать на другой. Шарды – исключительно внутренняя деталь реализации: вам не нужно знать, на каком из них находится ваш tailnet.
У каждого шарда есть своя база SQLite, где хранится вся информация о находящихся на нём tailnet. К этой базе эксклюзивно обращается один процесс на Go, который обслуживает управляющий контур для этих tailnet. Такая архитектура с одним писателем – именно тот сценарий, на который рассчитан SQLite.
Мы используем SQLite как основную базу данных с 2022 года. Мы выбрали его потому, что это известная, надёжная и широко распространённая технология. SQLite – «скучная технология», и в данном случае это комплимент. Многие компании без проблем используют SQLite в системах гораздо большего масштаба, и мы рассчитывали на такую же спокойную эксплуатацию.
В нашем нынешнем пайплайне резервного копирования каждые несколько минут создаётся полный снимок базы данных, после чего весь файл SQLite загружается в бакет S3. Такая схема без происшествий работала у нас с начала 2023 года.
Перенесёмся в август прошлого года. Пайплайн обработки данных, который читает эти резервные копии из S3, сообщил об ошибке в одной из баз. Мы запустили для бэкапа команду SQLite PRAGMA integrity_check и обнаружили, что база действительно повреждена. Повреждение базы SQLite возможно, но это крайне редкая ситуация, с которой при штатной работе сталкиваться не приходится. Мы восстановили пострадавшую базу и попытались выяснить причину, но безуспешно.
При работе в больших масштабах даже редкие события начинают происходить с заметной частотой, поэтому нас не должно было удивить, когда это случилось снова. А потом ещё раз. И ещё. И ещё. Всего за шесть месяцев мы столкнулись с 19 отдельными случаями повреждения базы данных, прежде чем наконец устранили лежавший в их основе баг.
Когда слышишь «повреждение базы данных», первая мысль – о потере данных. Но наш управляющий контур работает только с конфигурационными данными, поэтому в этих базах хранится метаинформация о вашем tailnet и устройствах, но никогда – ваши закрытые ключи шифрования или сетевой трафик. В первых инцидентах процесс восстановления приводил к тому, что несколько недавно добавленных устройств или изменений конфигурации не сохранялись, а небольшой объём метаданных приходилось вводить заново.
Каждый раз, когда база повреждалась, нам приходилось останавливать процесс управляющего контура на соответствующем шарде, пока мы восстанавливали базу или исправляли повреждения. Для tailnet на этом шарде это было весьма болезненно: на время восстановления их управляющий контур полностью становился недоступен. В первых инцидентах простой длился больше часа, но с каждым новым случаем мы постепенно ускоряли процедуру восстановления.
Каждый tailnet представляет собой mesh-сеть, устройства в которой устанавливают друг с другом прямые соединения через WireGuard. Когда устройство подключается к tailnet, оно сначала должно получить от управляющего контура список остальных устройств и только после этого может устанавливать новые соединения. Поэтому, если устройство появлялось в сети во время простоя SQLite, подключиться оно не могло. Уже работающие устройства продолжали поддерживать соединения друг с другом, пока мы восстанавливали базу, но не могли получать информацию об изменениях в сети. Кроме того, пользователи этих tailnet временно теряли доступ к веб-консоли администрирования и API Tailscale.
Есть и менее очевидное последствие – потеря доверия. Мы публикуем информацию об инциденте на нашей странице статуса даже тогда, когда проблема затрагивает лишь небольшое число tailnet. Поэтому многие видели сообщение об инциденте, который на них вообще не повлиял. Более того, большинство шардов и tailnet ни разу не столкнулись с повреждением базы данных. Но регулярные простои всё равно подрывают доверие, независимо от того, затронули они вас лично или нет.
Уже после первого случая повреждения мы поняли, что это серьёзная угроза надёжности сервиса, и бросили на проблему немало инженерных ресурсов. Но найти решение оказалось непросто.
Все наши первые попытки обнаружить баг ни к чему не привели.
Мы проверили недавние изменения, но ничего подозрительного среди них не нашли. Низкоуровневый код, который взаимодействует с SQLite, никто давно не трогал: его написали несколько лет назад, и до этого он не доставлял никаких проблем. Мы заново, буквально по строчке, перепроверили весь этот код в поисках пропущенных ранее ошибок, но так и не нашли ничего, что могло бы объяснить наблюдаемое повреждение базы.
Мы пытались найти что-то общее между инцидентами, но и здесь безуспешно. Проблема не была связана ни с конкретным шардом, ни с клиентом, ни с какой-либо функцией tailnet, ни со временем суток, ни с уровнем нагрузки. Мы совершенно не понимали, что именно может её провоцировать.
Из-за отсутствия воспроизводимых условий мы не могли искусственно вызвать баг. Поэтому пришлось развернуть в продакшене пассивную диагностическую телеметрию для расследования и попытаться поймать повреждение прямо в момент возникновения. Собирать такую диагностику на живой базе – последнее, чего нам хотелось, но другого варианта не было.
Ситуацию дополнительно осложняло то, что повреждения возникали без какой-либо периодичности. Иногда между инцидентами проходило несколько часов, иногда – несколько недель. Из-за этого было трудно оценивать прогресс и планировать дальнейшую работу: мы никогда не знали, когда получим следующий диагностический дамп. С октября по декабрь был шестинедельный период без единого случая повреждения, после чего проблема вернулась в качестве совершенно нежелательного рождественского подарка.
Поскольку стало понятно, что быстро и просто решить проблему не получится, мы обратились к разработчикам SQLite и заключили с ними договор на профессиональную поддержку. Это оказалось отличным решением. Мы получили прямой доступ к их глубокой экспертизе и опыту и провели множество подробных технических обсуждений нашей архитектуры и произошедших инцидентов.
Совместно с разработчиками ядра SQLite мы сформулировали несколько гипотез о причинах повреждения базы. Среди них были проблемы с POSIX-блокировками при close(), неправильная работа с памятью, принадлежащей SQLite, и случайное обращение к SQLite из нескольких потоков при отключённой потокобезопасности. После каждого нового инцидента мы собирали дополнительные данные, добавляли диагностику и методично исключали одну гипотезу за другой. Постепенно мы приближались к настоящей причине.
Но пока мы искали первопричину, нам всё равно нужно было поддерживать работающую платформу. Поэтому мы предприняли довольно жёсткие меры, чтобы автоматизировать восстановление и сократить время простоя:
Настроили шарды управляющего контура так, чтобы при обнаружении повреждения они немедленно полностью останавливались
Развернули автоматический мониторинг резервных копий, который непрерывно запускал для них PRAGMA integrity_check
Улучшили ранбуки и подготовку дежурных инженеров
Благодаря этому время реакции удалось сократить до менее чем часа. А затем мы наткнулись на неожиданную зацепку.
Нам нужен был способ восстановить работу сервиса без отката к последней заведомо исправной резервной копии, при котором терялось бы много данных, и без восстановления заведомо повреждённой базы, что само по себе могло быть рискованно.
Для этого мы построили пайплайн журналирования транзакций. Каждый SQL-запрос, изменявший базу данных, мы параллельно записывали в отдельный лог-файл. Поскольку SQLite – база данных с одним писателем и поддерживает сериализуемые транзакции, история транзакций у нас получалась строго линейной и детерминированной. (В базе с несколькими писателями, например Postgres или MySQL, это было бы не так.) Если повторно выполнить эти транзакции поверх последней заведомо исправной резервной копии, база должна восстановиться до самого свежего состояния, при этом повреждённые данные будут безопасно обойдены.
Пайплайн заработал, но затем принёс нам кое-что ещё более ценное: зацепку.
В двух инцидентах журналы транзакций не удалось воспроизвести без ошибок. При более внимательном разборе выяснилось, что данные, записанные и зафиксированные одной транзакцией, по непонятной причине были невидимы для последующих транзакций. Запись просто исчезла без единой ошибки. Такого происходить не должно!
Параллельно с этими инцидентами разработчики SQLite создавали новый инструмент для отладки. К тому моменту мы уже некоторое время подозревали, что баг скрывается где-то в процессе создания контрольной точки. Новый инструмент должен был дать больше информации о том, что именно происходит во время этой операции.
Чтобы понять, что он обнаружил, сначала нужно вкратце разобраться, как в SQLite устроены контрольные точки.
База данных SQLite состоит из набора «страниц» – небольших блоков данных. Когда вы обновляете базу, часть этих страниц приходится заменять новыми, уже с обновлённой информацией.
Для повышения производительности и параллелизма мы запускаем SQLite в режиме журналирования с упреждающей записью (Write-Ahead Logging, WAL). В этом режиме новые страницы записываются не напрямую в файл базы данных, а в журнал упреждающей записи – WAL-файл.
Бесконечно записывать новые страницы в WAL-файл нельзя: в какой-то момент их приходится переносить обратно в основной файл базы данных. Этот процесс называется созданием контрольной точки.
В большинстве случаев SQLite сам решает, когда создавать контрольную точку, и для пользователя и разработчика этот процесс остаётся незаметным. Но в нашем управляющем контуре мы берём создание контрольных точек под ручное управление, чтобы резервные копии получались быстро и консистентно. По мере того как мы исключали одну возможную причину за другой, этот нестандартный подход выглядел всё подозрительнее.
Одной из зацепок стали наши метрики: во время инцидентов с повреждением SQLite сообщал, что скопировал из WAL-файла больше страниц, чем там вообще было. Если в WAL-файле 10 страниц, а в базу якобы скопировано 20, очевидно, что что-то идёт не так.
Чтобы понять, что происходит во время таких некорректных контрольных точек, разработчики SQLite создали новый инструмент отладки для слоя виртуальной файловой системы.
SQLite состоит из нескольких слоёв. Верхний слой – парсер и генератор кода, который преобразует SQL-запросы во внутренние структуры данных SQLite. Затем эти структуры передаются пейджеру, который разбивает их на отдельные страницы для записи на диск. Непосредственной записью на диск занимается интерфейс ОС, или «виртуальная файловая система» (VFS). Сейчас у SQLite есть две основные реализации VFS – для Unix и Windows.
Если хочется глубже разобраться во внутреннем устройстве SQLite, рекомендую эту лекцию Ричарда Хиппа, основного автора SQLite.
Такая архитектура позволяет подменять отдельные слои другими реализациями или оборачивать существующий слой, чтобы получать дополнительную информацию о его работе. Для диагностики нашей проблемы разработчики SQLite создали обёртку над виртуальной файловой системой, которая записывает дополнительную трассировочную информацию и логи изменений базы данных. Этот shim-слой называется tmstmpvfs, а его исходный код доступен в публичном репозитории SQLite.
Мы развернули этот shim-слой в продакшене и стали ждать следующего повреждения. К счастью, ждать пришлось недолго.
После очередного инцидента дополнительные логи от нового tmstmpvfs позволили разработчикам SQLite найти и исправить баг: редкую гонку данных в исходном коде SQLite между созданием контрольной точки и транзакцией записи.
Если точнее, когда запись происходит в определённый момент во время создания контрольной точки, процесс сбивается: он считает, что некоторые страницы уже скопированы из WAL в основной файл базы данных, хотя на самом деле этого не произошло. В итоге эти страницы вообще не попадают в файл базы, а данные в них безвозвратно теряются. При этом другие страницы, которые ссылаются на потерянные, например страницы индекса, записываются в базу. В результате файл базы данных оказывается повреждён.
Разработчики SQLite назвали эту проблему багом WAL-Reset и считают, что она присутствовала в SQLite как минимум 16 лет. Так долго баг мог оставаться незамеченным из-за своей редкости – настолько большой, что разработчикам SQLite пришлось добавить специальный код, чтобы намеренно воспроизводить его в тестовом окружении. Исправление добавляет дополнительную проверку в функцию создания контрольной точки, которая определяет, не был ли WAL сброшен другим потоком.
Разработчики подтвердили, что именно этот баг объясняет всё странное поведение, которое мы наблюдали. Он был причиной и повреждения базы, и журналов транзакций, которые не удавалось корректно воспроизвести, и противоречивой статистики контрольных точек. Стало понятно и то, почему мы сталкивались с ним чаще других пользователей SQLite: мы вручную управляем созданием контрольных точек и запускаем их очень часто. Даже при крайне редком условии срабатывания рано или поздно этот баг должен был нас настигнуть.
Это был важный момент. После нескольких месяцев неопределённости и попыток понять, что происходит, у нас наконец появилась правдоподобная теория возникновения повреждений и исправление, которое можно было развернуть, чтобы их предотвратить.
Разработчики SQLite выпустили исправление в составе SQLite 3.52.0, и мы подготовились развернуть новую версию, как только она стала доступна.
SQLite 3.52.0 мы выкатывали осторожно: сначала на несколько канареечных шардов, а затем, убедившись, что всё работает стабильно, развернули на остальной управляющий контур.
И тут наш монитор резервных копий немедленно загорелся красным и сообщил о повреждении сразу 13 разных баз данных. Выглядело это крайне тревожно, но мы выполнили стандартные процедуры восстановления, исправили все предполагаемые повреждения, и после этого всё снова стало нормально. Как выяснилось, на самом деле эти базы не были повреждены – мы столкнулись со второй проблемой в этой версии SQLite.
Мы передали разработчикам SQLite информацию об ошибках, и это помогло обнаружить баг, связанный с устаревшими индексами по выражению. Если создать индекс по вычисляемому значению, а затем изменить способ вычисления, значения в индексе перестанут соответствовать фактическим данным, и PRAGMA integrity_check сообщит об этом как о повреждении базы.
В нашем случае некоторые временные метки высокой точности хранились в виде текста, а затем преобразовывались в числа с плавающей точкой в виртуальном генерируемом столбце (VIRTUAL generated column). В SQLite 3.52.0, где исправили нашу гонку данных, заодно появилась оптимизация, которая слегка изменила поведение округления при преобразовании текста в число с плавающей точкой. На наших канареечных шардах не оказалось временных меток, на которых проявлялось это изменение, поэтому при поэтапном развертывании мы проблему не заметили.
Поскольку это изменение приводило к ложным сообщениям о повреждении базы, разработчики SQLite отозвали релиз 3.52.0 и вместо него выпустили 3.51.3, куда вошло только исправление бага WAL-Reset.
Со своей стороны мы решили проблему, снизив точность временных меток до целых секунд: преобразование текста в целое число однозначно. Тем временем разработчики SQLite добавили в 3.53.0 автоматический механизм самовосстанавливающихся индексов, который предотвращает проблему с устаревшими индексами по выражению.
Когда исправление было развернуто на всём управляющем контуре, мы уже были готовы объявить победу, но всё ещё сохраняли осторожность. Само по себе отсутствие новых случаев повреждения ещё не доказывало, что проблема действительно решена: у нас уже был один обманчиво спокойный шестинедельный период.
Нам хотелось получить прямое подтверждение, что эта гонка данных действительно возникает в нашем продакшене. Теперь, когда мы понимали причину бага – одновременное совпадение транзакции записи и сброса WAL, – мы доработали драйвер SQLite так, чтобы он писал предупреждение в лог, если эти две операции пересекались по времени. Если предупреждение сработает, а база при этом не повредится, значит, исправление действительно спасло нас от потенциального инцидента.
Мы развернули это предупреждение и стали ждать. И ждать. И ещё ждать. И ещё. Шли недели, а нужного события всё не было, и мы начали сомневаться. Может быть, предупреждение не работает? Может быть, наша теория неверна? Может быть, настоящий баг всё ещё где-то прячется?
И вот спустя два месяца наконец сработал тот самый алерт:
Этот алерт доказал, что точные условия для возникновения бага WAL-Reset действительно встречаются в нашем продакшене. Значит, именно он, скорее всего, и был причиной шести месяцев нестабильной работы.
На момент написания статьи после этого странным образом радостного алерта прошло ещё четыре месяца без единого инцидента с базами данных. Наконец-то можно было выдохнуть.
Никто не хотел тратить шесть месяцев на поиски багов в SQLite. Этот период оказался чрезвычайно тяжёлым и для наших клиентов, и для команды, и мы все рады, что эта нестабильность осталась позади.
Это расследование хорошо напоминает об одном: использовать «скучную технологию» нестандартным способом – рискованно. Типовые сценарии и стандартные конфигурации проверены невероятно хорошо и отличаются высокой надёжностью. Большинство пользователей запускают SQLite в стандартной конфигурации и никогда не сталкиваются с подобными проблемами. Всё, что делали мы, было публично задокументировано и официально поддерживалось. Но, взяв создание контрольных точек под ручное управление и выполняя их с собственной высокой частотой, мы сошли с хорошо проторенного эксплуатационного пути.
Устранение этих инцидентов потребовало огромных усилий сразу от множества команд и десятков людей – включая инженеров и службу поддержки Tailscale, а также основных сопровождающих SQLite. Во многом благодаря им последствия этих сбоев оказались не намного серьёзнее.
Каким бы тяжёлым ни оказался этот период, сейчас мы находимся в более сильной позиции, чем раньше. Давний баг в SQLite исправлен, а по пути мы устранили ещё десятки сопутствующих проблем, которые обнаружили во время расследования. Мы профинансировали разработку открытого shim-слоя VFS для SQLite, который почти сразу помог локализовать гонку данных и пригодится для поиска похожих багов в будущем. Наконец, мы доработали процедуры резервного копирования и восстановления баз и больше десятка раз проверили их в реальных условиях.
Надеемся, что подобного инцидента с базой данных больше не случится. Но если случится, мы будем готовы.
Расследования редких сбоев требуют понимания сразу нескольких уровней системы — от хранения и восстановления данных до диагностики процессов в продакшене. Разобраться в этих темах глубже можно на бесплатных уроках OTUS:
21 сентября в 20:00. «Типовые задачи с RAID-массивами: создание, эксплуатация, перенос данных и восстановление». Записаться
23 сентября в 20:00. «eBPF: рентгеновское зрение для production». Записаться
Больше бесплатных уроков сентября смотрите в дайджесте.
