Подробное описание поисков бага из задачи GitLab, которые привели к патчу для ядра Linux
14 сентября служба поддержки GitLab сообщила о критической проблеме, которая возникла у одного из наших клиентов: сначала GitLab работает нормально, а потом у пользователей возникает ошибка. Они пытались клонировать некоторые репозитории через Git, и вдруг появлялось непонятное сообщение об устаревшем файле: Stale file error. Ошибка сохранялась надолго и не давала работать, пока системный администратор вручную не запускал ls в самом каталоге.
Пришлось изучать внутренние механизмы Git и сетевой файловой системы NFS. В итоге мы нашли баг в клиенте Linux v4.0 NFS, Тронд Мюклебуст (Trond Myklebust) написал патч для ядра, и с 26 октября этот патч входит в основное ядро Linux.
В этом посте я расскажу, как мы изучали проблему, в каком направлении думали и какие инструменты использовали, чтобы отследить баг. Мы вдохновлялись отличной детективной работой Олега Дашевского, описанной в посте «Как я две недели охотился за утечкой памяти в Ruby».
А еще это отличный пример того, что отладка ПО с открытым исходным кодом — это командный спорт, в котором участвует много людей, компаний и стран. Девиз GitLab «Каждый может внести свой вклад» справедлив не только для самого GitLab, но и для других проектов с открытым исходным кодом, например для ядра Linux.
Воспроизведение бага
Мы много лет держали NFS на GitLab.com, но потом перестали использовать его для доступа к данным репозиториев на машинах с приложениями. Мы перенесли все вызовы Git в Gitaly. Мы поддерживаем NFS для клиентов, которые управляют своими инсталляциями на GitLab, но никогда не встречали такую проблему, как у вышеупомянутого клиента.
Клиент дал несколько полезных подсказок:
- Полный текст ошибки:
fatal: Couldn't read ./packed-refs: Stale file handle. - Судя по всему, проблема возникала, когда клиент вручную запускал сборку мусора в Git командой
git gc. - Ошибка пропадала, когда системный администратор запускал утилиту
lsв каталоге. - Ошибка пропадала, когда процесс
git gcзавершался.
Понятно, что первые два пункта связаны. Когда вы отправляете изменения в ветку Git, Git создает слабую ссылку — длинное имя файла, которое указывает имя ветки для коммита. Например, при отправке в master будет создан файл с именем refs/heads/master в репозитории:
$ cat refs/heads/master
2e33a554576d06d9e71bfd6814ee9ba3a7838963Команда git gc выполняет несколько задач. Например, собирает эти слабые ссылки (refs) и упаковывает их в один файл с именем packed-refs. Это немного ускоряет работу, ведь прочитать один большой файл проще, чем много маленьких. Например, после запуска команды git gc файл packed-refs может выглядеть как-то так:
# pack-refs with: peeled fully-peeled sorted
564c3424d6f9175cf5f2d522e10d20d781511bf1 refs/heads/10-8-stable
edb037cbc85225261e8ede5455be4aad771ba3bb refs/heads/11-0-stable
94b9323033693af247128c8648023fe5b53e80f9 refs/heads/11-1-stable
2e33a554576d06d9e71bfd6814ee9ba3a7838963 refs/heads/masterКак создается файл packed-refs? Чтобы это узнать, мы запустили команду strace git gc там, где у нас была слабая ссылка. Вот строки, которые относятся к делу:
28705 open("/tmp/libgit2/.git/packed-refs.lock", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0666) = 3
28705 open(".git/packed-refs", O_RDONLY) = 3
28705 open("/tmp/libgit2/.git/packed-refs.new", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0666) = 4
28705 rename("/tmp/libgit2/.git/packed-refs.new", "/tmp/libgit2/.git/packed-refs") = 0
28705 unlink("/tmp/libgit2/.git/packed-refs.lock") = 0Системные вызовы показали, что команда git gc:
- Открыла
packed-refs.lock. Это говорит другим процессам, что файлpacked-refsзаблокирован и не может меняться. - Открыла
packed-refs.new. - Записала слабые ссылки в
packed-refs.new. - Переименовала
packed-refs.newвpacked-refs. - Удалила
packed-refs.lock. - Удалила слабые ссылки.
Ключевой пункт здесь — четвертый, то есть переименование, где Git вводит файл packed-refs. git gc не только собирает слабые ссылки, но и выполняет куда более ресурсоемкую задачу — ищет и удаляет неиспользуемые объекты. В больших репозиториях это может длиться больше часа.
И мы спросили себя: а в больших репозиториях держит ли git gc файл открытым во время очистки? Мы изучили логи strace, запустили утилиту lsof, и вот что узнали о процессе git gc:
Как видно, файл packed-refs закрывается в самом конце, после потенциально долгого процесса Garbage collect objects.
Так возник следующий вопрос: как ведет себя NFS, когда на одной ноде открыт файл packed-refs, а другая в это время переименовывает его?
"В научных целях" мы попросили клиента провести один эксперимент на двух разных машинах (Элис и Боб):
1) В общем томе NFS создайте два файла: test1.txt и test2.txt с разным содержимым, чтобы их было проще различать:
alice $ echo "1 - Old file" > /path/to/nfs/test1.txt
alice $ echo "2 - New file" > /path/to/nfs/test2.txt2) На машине Элис файл test1.txt должен быть открыт:
alice $ irb
irb(main):001:0> File.open('/path/to/nfs/test1.txt')3) На машине Элис непрерывно показывайте содержимое test1.txt:
alice $ while true; do cat test1.txt; done4) Затем на машине Боб выполните команду:
bob $ mv -f test2.txt test1.txtПоследний шаг воспроизводит то, что делает git gc с файлом packed-refs, когда перезаписывает существующий файл.
На машине клиента результат выглядел примерно так:
1 - Old file
1 - Old file
1 - Old file
cat: test1.txt: Stale file handleЕсть! Кажется, мы контролируемо воспроизвели проблему. Но в этом же эксперименте на Linux NFS-сервере такая проблема не возникла. Результат был ожидаемым — после переименования принималось новое содержимое:
1 - Old file
1 - Old file
1 - Old file
2 - New file <--- RENAME HAPPENED
2 - New file
2 - New fileОткуда эта разница в поведении? Оказывается, клиент использовал хранилище Isilon NFS, которое поддерживало только NFS v4.0. Когда мы изменили параметры подключения на v4.0 с помощью параметра vers=4.0 в /etc/fstab, тест показал другой результат для Linux NFS-сервера:
1 - Old file
1 - Old file
1 - Old file
1 - Old file <--- RENAME HAPPENED
1 - Old file
1 - Old fileВместо устаревшего дескриптора файла Stale file handle сервер Linux NFS v4.0 показывал устаревшее содержимое. Оказывается, разницу в поведении можно объяснить спецификациями NFS. Из RFC 3010:
Дескриптор файла может устареть или потерять силу при переименовании, но не всегда. Специалистам по внедрению серверов рекомендуется принять меры, чтобы дескрипторы файлов не устаревали и не теряли силу таким образом.
Иными словами, NFS-серверы могут выбирать, как себя вести, когда файл переименован, и NFS-сервер вполне обоснованно возвращает ошибку Stale file error в таких случаях. Мы предположили, что причина проблемы — та же, хотя результаты и были разными. Мы подозревали, что дело в проверке кэша, ведь утилита ls в каталоге убирала ошибку. Теперь у нас был воспроизводимый тестовый сценарий, и мы обратились к экспертам — мейнтейнерам Linux NFS.
Ложный след: делегирование на NFS-сервере
Когда мы сумели пошагово воспроизвести ошибку, я написал контактам по Linux NFS о том, что мы узнали. Неделю я переписывался с Брюсом Филдсом, мейнтейнером Linux NFS-сервера, и он предположил, что баг в NFS и нужно изучить сетевой трафик. Он думал, что проблема в делегировании задач на NFS-сервере.
Что такое делегирование на NFS-сервере?
В двух словах, в версии NFS v4 появилась функция делегирования для ускорения доступа к файлам. Сервер может делегировать доступ на чтение или запись клиенту, чтобы клиенту не пришлось постоянно спрашивать у сервера, не изменен ли файл другим клиентом. Проще говоря, делегирование записи — это как одолжить кому-то свой блокнот и сказать: «Ты пока тут пиши, а я заберу его, когда буду готов». И человеку не придется просить блокнот каждый раз, когда нужно что-то записать — у него есть полная свобода действий, пока блокнот не отнимут. В NFS просьба вернуть блокнот называется отзывом делегирования.
Баг в отзыве делегирования в NFS мог бы объяснить проблему Stale file handle. Помните, как в нашем эксперименте у Элис был открыт test1.txt, а потом его заменил test2.txt. Может быть, серверу не удалось отозвать делегирование для test1.txt, и это привело к неверному статусу. Чтобы проверить эту теорию, мы записали трафик NFC утилитой tcpdump и визуализировали его с помощью Wireshark.
Wireshark — это отличный инструмент с открытым исходным кодом для анализа сетевого трафика, особенно для изучения NFS в действии. Мы записали трассировку с помощью следующей команды на NFS-сервере:
tcpdump -s 0 -w /tmp/nfs.pcap port 2049Эта команда записывает весь NFS-трафик, который обычно проходит через порт TCP 2049. Раз наш эксперимент удался с NFS v4.1, но не с NFS v4.0, мы могли сравнить поведение NFS в рабочем и нерабочем случае. С Wireshark мы увидели следующее поведение:
NFS v4.0 (устаревший файл)
На этой схеме видно, что в шаге 1 Элис открывает test1.txt и получает дескриптор файла NFS с идентификатором stateid 0x3000. Когда Боб пытается переименовать файл, NFS-сервер просит повторить попытку, отправляя сообщение NFS4ERR_DELAY, а сам отзывает делегирование у Элис через сообщение CB_RECALL (шаг 3). Элис возвращает делегирование (DELEGRETURN на шаге 4), и Боб пытается отправить сообщение RENAME еще раз (шаг 5). RENAME выполняется в обоих случаях, но Элис продолжает считывать файл по тому же дескриптору.
NFS v4.1 (рабочий случай)
Здесь разница видна в шаге 6. В NFS v4.0 (с устаревшим файлом) Элис пытается снова использовать тот же stateid. В NFS v4.1 (рабочий случай) Элис выполняет дополнительные операции LOOKUP и OPEN, так что сервер возвращает другой stateid. В v4.0 она не посылает никаких дополнительных сообщений. Это объясняет, почему Элис видит устаревшее содержимое — она использует старый дескриптор.
Почему Элис вдруг решается на дополнительный LOOKUP? Судя по всему, отзыв делегирования прошел успешно, но какая-то проблема, видимо, осталась. Например, пропущен шаг инвалидации. Чтобы это проверить, мы исключили делегирование NFS на самом NFS-сервере этой командой:
echo 0 > /proc/sys/fs/leases-enableМы повторили эксперимент, но проблема никуда не делась. Мы убедились, что проблема не в NFS-сервере или делегировании, и решили посмотреть на NFS-клиент в ядре.
Копаем глубже: Linux NFS-клиент
Первый вопрос, на который мы должны были ответить мейнтейнерам NFS:
Эта проблема сохраняется в последней версии ядра?
Проблема возникала в ядрах CentOS 7.2 и Ubuntu 16.04 с версиями 3.10.0-862.11.6 и 4.4.0-130 соответственно. Но оба ядра отставали от последней версии, которой на тот момент была 4.19-rc2.
Мы развернули новую виртуальную машину Ubuntu 16.04 на платформе Google Cloud Platform (GCP), клонировали последнее ядро Linux и настроили среду разработки ядра. Мы создали файл .config с помощью menuconfig и проверили, что:
- Драйвер NFS скомпилирован как модуль (
CONFIG_NFSD=m). - Нужные параметры ядра GCP указаны верно.
Генетики отслеживают эволюцию в реальном времени по дрозофилам, а мы с помощью первого пункта могли по-быстрому вносить правки в NFS-клиент, не перезапуская ядро. Второй пункт гарантировал, что ядро запустится после установки. К счастью, нас устроили параметры ядра по умолчанию.
Мы убедились, что проблема устаревшего файла никуда не делась в последней версии ядра. Мы спросили себя:
- Где именно возникает проблема?
- Почему это происходит в NFS v4.0, но не в v4.1?
Чтобы ответить на эти вопросы, мы углубились в исходный код NFS. Отладчика ядра у нас не было, так что мы посылали в исходный код вызовы двух типов:
pr_info()(раньше это был printk).dump_stack(): он показывает трассировку стека для текущего вызова функции.
Например, первым делом мы подключились к функции nfs4_file_open() в fs/nfs/nfs4file.c:
static int
nfs4_file_open(struct inode *inode, struct file *filp)
{
...
pr_info("nfs4_file_open startn");
dump_stack();Конечно, мы могли бы активировать сообщения dprintk с динамической отладкой Linux или использовать rpcdebug, но мы хотели добавлять свои сообщения, чтобы проверять изменения.
После каждого изменения мы перекомпилировали модуль и переустанавливали его в ядро с помощью команд:
make modules
sudo umount /mnt/nfs-test
sudo rmmod nfsv4
sudo rmmod nfs
sudo insmod fs/nfs/nfs.ko
sudo mount -aС модулем NFS мы могли повторять эксперименты и получать сообщения, чтобы разобраться в коде NFS. Например, сразу видно, что происходит, когда приложение вызывает open():
Sep 24 20:20:38 test-kernel kernel: [ 1145.233460] Call Trace:
Sep 24 20:20:38 test-kernel kernel: [ 1145.233462] dump_stack+0x8e/0xd5
Sep 24 20:20:38 test-kernel kernel: [ 1145.233480] nfs4_file_open+0x56/0x2a0 [nfsv4]
Sep 24 20:20:38 test-kernel kernel: [ 1145.233488] ? nfs42_clone_file_range+0x1c0/0x1c0 [nfsv4]
Sep 24 20:20:38 test-kernel kernel: [ 1145.233490] do_dentry_open+0x1f6/0x360
Sep 24 20:20:38 test-kernel kernel: [ 1145.233492] vfs_open+0x2f/0x40
Sep 24 20:20:38 test-kernel kernel: [ 1145.233493] path_openat+0x2e8/0x1690
Sep 24 20:20:38 test-kernel kernel: [ 1145.233496] ? mem_cgroup_try_charge+0x8b/0x190
Sep 24 20:20:38 test-kernel kernel: [ 1145.233497] do_filp_open+0x9b/0x110
Sep 24 20:20:38 test-kernel kernel: [ 1145.233499] ? __check_object_size+0xb8/0x1b0
Sep 24 20:20:38 test-kernel kernel: [ 1145.233501] ? __alloc_fd+0x46/0x170
Sep 24 20:20:38 test-kernel kernel: [ 1145.233503] do_sys_open+0x1ba/0x250
Sep 24 20:20:38 test-kernel kernel: [ 1145.233505] ? do_sys_open+0x1ba/0x250
Sep 24 20:20:38 test-kernel kernel: [ 1145.233507] __x64_sys_openat+0x20/0x30
Sep 24 20:20:38 test-kernel kernel: [ 1145.233508] do_syscall_64+0x65/0x130Что это за вызовы do_dentry_open и vfs_open? В Linux есть виртуальная файловая система (virtual filesystem, VFS) — слой абстракции, который предоставляет общий интерфейс для всех файловых систем. В документации по VFS говорится:
VFS реализует open(2), stat(2), chmod(2) и другие системные вызовы. Система VFS использует аргумент имени пути, который им передается, для поиска по кэшу записей каталога (dentry-кэш, или dcache). Это обеспечивает очень быстрый механизм поиска, который преобразует имя пути (или имя файла) в конкретный dentry. Dentry находятся в RAM и никогда не сохраняются на диске — они существуют только для производительности.
И нас осенило — а что если проблема в dentry-кэше?
Мы заметили, что dentry-кэш обычно проверяется в fs/nfs/dir.c. Особенно нас заинтересовала функция nfs4_lookup_revalidate(), и в качестве эксперимента мы заставили ее сработать раньше:
diff --git a/fs/nfs/dir.c b/fs/nfs/dir.c
index 8bfaa658b2c1..ad479bfeb669 100644
--- a/fs/nfs/dir.c
+++ b/fs/nfs/dir.c
@@ -1159,6 +1159,7 @@ static int nfs_lookup_revalidate(struct dentry *dentry, unsigned int flags)
trace_nfs_lookup_revalidate_enter(dir, dentry, flags);
error = NFS_PROTO(dir)->lookup(dir, &dentry->d_name, fhandle, fattr, label);
trace_nfs_lookup_revalidate_exit(dir, dentry, flags, error);
+ goto out_bad;
if (error == -ESTALE || error == -ENOENT)
goto out_bad;
if (error)И в этом эксперименте проблема устаревшего файла не возникла! Наконец, мы напали на след.
Чтобы узнать, почему проблема не возникала в NFS v4.1, мы добавили вызовы pr_info() в каждый блок if в этой функции. Мы поэкспериментировали с NFS v4.0 и v4.1 и нашли особое условие в версии v4.1:
if (NFS_SB(dentry->d_sb)->caps & NFS_CAP_ATOMIC_OPEN_V1) {
goto no_open;
}Что такое NFS_CAP_ATOMIC_OPEN_V1? В этом патче к ядру говорится, что это функция версии NFS v4.1, и код в fs/nfs/nfs4proc.c подтвердил, что этот параметр есть в v4.1, но отсутствует в v4.0:
static const struct nfs4_minor_version_ops nfs_v4_1_minor_ops = {
.minor_version = 1,
.init_caps = NFS_CAP_READDIRPLUS
| NFS_CAP_ATOMIC_OPEN
| NFS_CAP_POSIX_LOCK
| NFS_CAP_STATEID_NFSV41
| NFS_CAP_ATOMIC_OPEN_V1Поэтому версии вели себя по-разному — в v4.1 goto no_open вызывает больше проверок в функции nfs_lookup_revalidate(), а в v4.0 функция nfs4_lookup_revalidate() возвращается раньше. И как мы в итоге решили проблему?
Решение
Я рассказал о наших находках в рассылке по NFS и предложил примитивный патч. Через неделю Тронд Мюклебуст отправил в рассылке серию патчей с исправлением бага и нашел еще одну связанную проблему в NFS v4.1.
Оказывается, исправление для бага NFS v4.0 было глубже в базе кода, чем мы думали. Тронд хорошо описал это в патче:
Нужно сделать так, чтобы inode и dentry правильно перепроверялись, когда открывается уже открытый файл. Сейчас мы не перепроверяем ни то, ни другое в NFSv4.0, потому что открытый файл кэширован. Давайте это исправим и будем кэшировать открытые файлы только в особых случаях — для восстановления открытых файлов и возврата делегирования.
Мы убедились, что это исправление решило проблему устаревшего файла, и отправили отчеты о багах командам Ubuntu и RedHat.
Мы прекрасно понимали, что изменения окажутся в стабильной версии ядра еще не скоро, так что добавили временное решение этой проблемы в Gitaly. Мы поэкспериментировали и проверили, что вызов stat() в файле packed-refs заставляет ядро перепроверять переименованный файл в dentry-кэше. Для простоты мы реализовали это в Gitaly для любых файловых систем, не только для NFS. Проверка выполняется только один раз, прежде чем Gitaly открывает репозиторий, а для других файлов уже есть другие вызовы stat().
Чему мы научились
Баг может прятаться в любом уголке стека программного обеспечения, и иногда искать его нужно за пределами приложения. Если у вас есть полезные связи в мире открытого исходного кода, это облегчит ваш труд.
Огромное спасибо Тронду Мюклебусту за то, что исправил проблему, и Брюсу Филдсу за то, что ответил на наши вопросы и помог разобраться в NFS. Именно за такую отзывчивость и профессионализм мы ценим сообщество разработчиков открытого исходного кода.
Автор: nAbdullin
