Подробное описание поисков бага из задачи 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, но никогда не встречали такую проблему, как у вышеупомянутого клиента.

Клиент дал несколько полезных подсказок:

1. Полный текст ошибки: fatal: Couldn't read ./packed-refs: Stale file handle.
2. Судя по всему, проблема возникала, когда клиент вручную запускал сборку мусора в Git командой git gc.
3. Ошибка пропадала, когда системный администратор запускал утилиту ls в каталоге.
4. Ошибка пропадала, когда процесс 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:

1. Открыла packed-refs.lock. Это говорит другим процессам, что файл packed-refs заблокирован и не может меняться.
2. Открыла packed-refs.new.
3. Записала слабые ссылки в packed-refs.new.
4. Переименовала packed-refs.new в packed-refs.
5. Удалила packed-refs.lock.
6. Удалила слабые ссылки.

Ключевой пункт здесь — четвертый, то есть переименование, где 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.txt

2) На машине Элис файл 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; done

4) Затем на машине Боб выполните команду:

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 и проверили, что:

1. Драйвер NFS скомпилирован как модуль (CONFIG_NFSD=m).
2. Нужные параметры ядра GCP указаны верно.

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

Мы убедились, что проблема устаревшего файла никуда не делась в последней версии ядра. Мы спросили себя:

1. Где именно возникает проблема?
2. Почему это происходит в NFS v4.0, но не в v4.1?

Чтобы ответить на эти вопросы, мы углубились в исходный код NFS. Отладчика ядра у нас не было, так что мы посылали в исходный код вызовы двух типов:

1. pr_info() (раньше это был printk).
2. 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 start\n");
        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. Именно за такую отзывчивость и профессионализм мы ценим сообщество разработчиков открытого исходного кода.