Хабрахабр

[Перевод] Как мы две недели охотились на баг NFS в ядре Linux

Подробное описание поисков бага из задачи GitLab, которые привели к патчу для ядра Linux

Они пытались клонировать некоторые репозитории через Git, и вдруг появлялось непонятное сообщение об устаревшем файле: Stale file error. 14 сентября служба поддержки GitLab сообщила о критической проблеме, которая возникла у одного из наших клиентов: сначала GitLab работает нормально, а потом у пользователей возникает ошибка. Ошибка сохранялась надолго и не давала работать, пока системный администратор вручную не запускал ls в самом каталоге.

В итоге мы нашли баг в клиенте Linux v4. Пришлось изучать внутренние механизмы Git и сетевой файловой системы NFS. 0 NFS, Тронд Мюклебуст (Trond Myklebust) написал патч для ядра, и с 26 октября этот патч входит в основное ядро Linux.

Мы вдохновлялись отличной детективной работой Олега Дашевского, описанной в посте «Как я две недели охотился за утечкой памяти в Ruby». В этом посте я расскажу, как мы изучали проблему, в каком направлении думали и какие инструменты использовали, чтобы отследить баг.

Девиз GitLab «Каждый может внести свой вклад» справедлив не только для самого GitLab, но и для других проектов с открытым исходным кодом, например для ядра Linux. А еще это отличный пример того, что отладка ПО с открытым исходным кодом — это командный спорт, в котором участвует много людей, компаний и стран.

Воспроизведение бага

Мы перенесли все вызовы Git в Gitaly. Мы много лет держали NFS на GitLab.com, но потом перестали использовать его для доступа к данным репозиториев на машинах с приложениями. Мы поддерживаем 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

Например, собирает эти слабые ссылки (refs) и упаковывает их в один файл с именем packed-refs. Команда git gc выполняет несколько задач. Например, после запуска команды 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

Чтобы это узнать, мы запустили команду strace git gc там, где у нас была слабая ссылка. Как создается файл packed-refs? Вот строки, которые относятся к делу:

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 gc не только собирает слабые ссылки, но и выполняет куда более ресурсоемкую задачу — ищет и удаляет неиспользуемые объекты. Ключевой пункт здесь — четвертый, то есть переименование, где Git вводит файл packed-refs. В больших репозиториях это может длиться больше часа.

Мы изучили логи strace, запустили утилиту lsof, и вот что узнали о процессе git gc: И мы спросили себя: а в больших репозиториях держит ли git gc файл открытым во время очистки?

image

Как видно, файл 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. Откуда эта разница в поведении? Когда мы изменили параметры подключения на v4. 0. 0 в /etc/fstab, тест показал другой результат для Linux NFS-сервера: 0 с помощью параметра vers=4.

1 - Old file
1 - Old file
1 - Old file
1 - Old file <--- RENAME HAPPENED
1 - Old file
1 - Old file

0 показывал устаревшее содержимое. Вместо устаревшего дескриптора файла Stale file handle сервер Linux NFS v4. Из RFC 3010: Оказывается, разницу в поведении можно объяснить спецификациями NFS.

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

Мы предположили, что причина проблемы — та же, хотя результаты и были разными. Иными словами, NFS-серверы могут выбирать, как себя вести, когда файл переименован, и NFS-сервер вполне обоснованно возвращает ошибку Stale file error в таких случаях. Теперь у нас был воспроизводимый тестовый сценарий, и мы обратились к экспертам — мейнтейнерам Linux NFS. Мы подозревали, что дело в проверке кэша, ведь утилита ls в каталоге убирала ошибку.

Ложный след: делегирование на NFS-сервере

Неделю я переписывался с Брюсом Филдсом, мейнтейнером Linux NFS-сервера, и он предположил, что баг в NFS и нужно изучить сетевой трафик. Когда мы сумели пошагово воспроизвести ошибку, я написал контактам по Linux NFS о том, что мы узнали. Он думал, что проблема в делегировании задач на NFS-сервере.

Что такое делегирование на NFS-сервере?

Сервер может делегировать доступ на чтение или запись клиенту, чтобы клиенту не пришлось постоянно спрашивать у сервера, не изменен ли файл другим клиентом. В двух словах, в версии NFS v4 появилась функция делегирования для ускорения доступа к файлам. И человеку не придется просить блокнот каждый раз, когда нужно что-то записать — у него есть полная свобода действий, пока блокнот не отнимут. Проще говоря, делегирование записи — это как одолжить кому-то свой блокнот и сказать: «Ты пока тут пиши, а я заберу его, когда буду готов». В NFS просьба вернуть блокнот называется отзывом делегирования.

Помните, как в нашем эксперименте у Элис был открыт test1.txt, а потом его заменил test2.txt. Баг в отзыве делегирования в NFS мог бы объяснить проблему Stale file handle. Чтобы проверить эту теорию, мы записали трафик NFC утилитой tcpdump и визуализировали его с помощью Wireshark. Может быть, серверу не удалось отозвать делегирование для test1.txt, и это привело к неверному статусу.

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

tcpdump -s 0 -w /tmp/nfs.pcap port 2049

Раз наш эксперимент удался с NFS v4. Эта команда записывает весь NFS-трафик, который обычно проходит через порт TCP 2049. 0, мы могли сравнить поведение NFS в рабочем и нерабочем случае. 1, но не с NFS v4. С Wireshark мы увидели следующее поведение:

NFS v4.0 (устаревший файл)

image

Когда Боб пытается переименовать файл, NFS-сервер просит повторить попытку, отправляя сообщение NFS4ERR_DELAY, а сам отзывает делегирование у Элис через сообщение CB_RECALL (шаг 3). На этой схеме видно, что в шаге 1 Элис открывает test1.txt и получает дескриптор файла NFS с идентификатором stateid 0x3000. RENAME выполняется в обоих случаях, но Элис продолжает считывать файл по тому же дескриптору. Элис возвращает делегирование (DELEGRETURN на шаге 4), и Боб пытается отправить сообщение RENAME еще раз (шаг 5).

NFS v4.1 (рабочий случай)

image

В NFS v4. Здесь разница видна в шаге 6. В NFS v4. 0 (с устаревшим файлом) Элис пытается снова использовать тот же stateid. В v4. 1 (рабочий случай) Элис выполняет дополнительные операции LOOKUP и OPEN, так что сервер возвращает другой stateid. Это объясняет, почему Элис видит устаревшее содержимое — она использует старый дескриптор. 0 она не посылает никаких дополнительных сообщений.

Судя по всему, отзыв делегирования прошел успешно, но какая-то проблема, видимо, осталась. Почему Элис вдруг решается на дополнительный LOOKUP? Чтобы это проверить, мы исключили делегирование NFS на самом NFS-сервере этой командой: Например, пропущен шаг инвалидации.

echo 0 > /proc/sys/fs/leases-enable

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

Копаем глубже: Linux NFS-клиент

Первый вопрос, на который мы должны были ответить мейнтейнерам NFS:

Эта проблема сохраняется в последней версии ядра?

2 и Ubuntu 16. Проблема возникала в ядрах CentOS 7. 10. 04 с версиями 3. 11. 0-862. 4. 6 и 4. Но оба ядра отставали от последней версии, которой на тот момент была 4. 0-130 соответственно. 19-rc2.

04 на платформе Google Cloud Platform (GCP), клонировали последнее ядро Linux и настроили среду разработки ядра. Мы развернули новую виртуальную машину Ubuntu 16. Мы создали файл .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

Например, сразу видно, что происходит, когда приложение вызывает open(): С модулем NFS мы могли повторять эксперименты и получать сообщения, чтобы разобраться в коде NFS.

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

В Linux есть виртуальная файловая система (virtual filesystem, VFS) — слой абстракции, который предоставляет общий интерфейс для всех файловых систем. Что это за вызовы do_dentry_open и vfs_open? В документации по VFS говорится:

Система VFS использует аргумент имени пути, который им передается, для поиска по кэшу записей каталога (dentry-кэш, или dcache). VFS реализует open(2), stat(2), chmod(2) и другие системные вызовы. Dentry находятся в RAM и никогда не сохраняются на диске — они существуют только для производительности. Это обеспечивает очень быстрый механизм поиска, который преобразует имя пути (или имя файла) в конкретный dentry.

И нас осенило — а что если проблема в dentry-кэше?

Особенно нас заинтересовала функция nfs4_lookup_revalidate(), и в качестве эксперимента мы заставили ее сработать раньше: Мы заметили, что dentry-кэш обычно проверяется в fs/nfs/dir.c.

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)

Наконец, мы напали на след. И в этом эксперименте проблема устаревшего файла не возникла!

1, мы добавили вызовы pr_info() в каждый блок if в этой функции. Чтобы узнать, почему проблема не возникала в NFS v4. 0 и v4. Мы поэкспериментировали с NFS v4. 1: 1 и нашли особое условие в версии v4.

if (NFS_SB(dentry->d_sb)->caps & NFS_CAP_ATOMIC_OPEN_V1)

В этом патче к ядру говорится, что это функция версии NFS v4. Что такое NFS_CAP_ATOMIC_OPEN_V1? 1, но отсутствует в v4. 1, и код в fs/nfs/nfs4proc.c подтвердил, что этот параметр есть в 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

1 goto no_open вызывает больше проверок в функции nfs_lookup_revalidate(), а в v4. Поэтому версии вели себя по-разному — в v4. И как мы в итоге решили проблему? 0 функция nfs4_lookup_revalidate() возвращается раньше.

Решение

Через неделю Тронд Мюклебуст отправил в рассылке серию патчей с исправлением бага и нашел еще одну связанную проблему в NFS v4. Я рассказал о наших находках в рассылке по NFS и предложил примитивный патч. 1.

0 было глубже в базе кода, чем мы думали. Оказывается, исправление для бага NFS v4. Тронд хорошо описал это в патче:

Сейчас мы не перепроверяем ни то, ни другое в NFSv4. Нужно сделать так, чтобы inode и dentry правильно перепроверялись, когда открывается уже открытый файл. Давайте это исправим и будем кэшировать открытые файлы только в особых случаях — для восстановления открытых файлов и возврата делегирования. 0, потому что открытый файл кэширован.

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

Мы поэкспериментировали и проверили, что вызов stat() в файле packed-refs заставляет ядро перепроверять переименованный файл в dentry-кэше. Мы прекрасно понимали, что изменения окажутся в стабильной версии ядра еще не скоро, так что добавили временное решение этой проблемы в Gitaly. Проверка выполняется только один раз, прежде чем Gitaly открывает репозиторий, а для других файлов уже есть другие вызовы stat(). Для простоты мы реализовали это в Gitaly для любых файловых систем, не только для NFS.

Чему мы научились

Если у вас есть полезные связи в мире открытого исходного кода, это облегчит ваш труд. Баг может прятаться в любом уголке стека программного обеспечения, и иногда искать его нужно за пределами приложения.

Именно за такую отзывчивость и профессионализм мы ценим сообщество разработчиков открытого исходного кода. Огромное спасибо Тронду Мюклебусту за то, что исправил проблему, и Брюсу Филдсу за то, что ответил на наши вопросы и помог разобраться в NFS.

Теги
Показать больше

Похожие статьи

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *

Кнопка «Наверх»
Закрыть