История Одного Бага

Буквально вчера мне пришлось столкнуться с одним очень тонким и специфическим багом.

Ошибка оказалась функцией, которая наткнулась на другую ошибку.

Исследуя проблему, мне пришлось изучить несколько особенностей Debian, потратить 4 часа времени и получить большой опыт. Я представляю несколько более изящную хронологию событий; Надеюсь, кому-то будет интересно посмотреть, как работают системные администраторы.

Фон

История одного бага

При развертывании тестового стенда из нескольких одинаковых серверов мне хотелось иметь возможность запускать нужные версии приложения без ручного обновления кода на куче хостов.

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

При загрузке общий ресурс монтировался в каталог /opt, и оттуда запускались приложения с помощью сценария rc.local. Поскольку речь шла об экспериментальном стенде с очень частыми изменениями кода, то было лень играть роль честного разработчика (пакеты, репозиторий, обновления, скрипты init.d).

Все произошло под Debian Squeeze. Шар прописан в /etc/fstab, необходимые тесты запущены в rc.local. Казалось бы, все сделано.

И тут я наткнулся на Мистик.

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

Более того, с /opt. Из других каталогов они работали нормально.

При этом запускаешь rc.local вручную - 100% все нормально.

При загрузке - успешный запуск раз из пяти, а то и реже.

Поначалу я не воспринимал эту проблему как серьезную и старался решить ее поспешно.

Поскольку проблема возникла только для /opt, я добавил команду ls -a1 /opt > /var/log/ls в rc.local. Как и ожидалось, на момент выполнения rc.local в /opt было только два файла — точка и две точки.

Другими словами, общий ресурс NFS не был смонтирован.

Иногда.

И иногда его редактировали.

Очевидно, что ситуация «иногда монтируется, иногда нет» (несмотря на то, что после входа в систему я всегда видел шару смонтированной) означает ровно одно — состояние гонки между монтированием шары и запуском rc.local. Давайте начнем решать Гипотеза: Debian Squeeze (а всё было основано на сжатии) перешёл на новую систему зависимостей для скриптов инициализации.

Я добавил прямую зависимость от $mountnfs в /etc/init.d/rc.local (сценарий инициализации, вызывающий /etc/rc.local) (то есть я потребовал, чтобы сценарий запускался после mountnfs).

Это помогло.

По забавному совпадению целых две перезагрузки подряд. Дальше все продолжалось как было – иногда успех, часто нет. Я был удивлён, ведь nfs шары монтируются на уровне запуска S, а rc.local запускается на втором уровне запуска (то есть позже, чем S).

Я добавил сакраментальную строку ls -a1 /opt > > /var/log/ls в скрипт /etc/init.d/rc — это скрипт, который выполняет все остальные скрипты из /etc/init.d. Если быть точнее, он читает каталоги /etc/rcS.d, /etc/rc2.d и т.д. и в зависимости от первой буквы (K или S) запускает оттуда скрипты с параметром stop или start. Сами эти каталоги содержат символические ссылки на сценарии в /etc/init.d, называемые S10service. S (или K) обозначает старт (kill), число позволяет организовать порядок запуска скриптов.

Итак, в самом конце /etc/init.d/rc я добавил еще один ls. Перезагрузился.

В журнале я обнаружил три набора вывода ls (один выполнялся во время выключения, два при запуске — это уровни «S» и «2»).

Удивительно, но последние два оказались пусты.

То есть по окончании выполнения скриптов перехода на уровень запуска 2 шара всё равно не монтируется! Другими словами, система зависимости скриптов, порядок запуска и т.п.

не играют никакой роли - на момент завершения загрузки шаров нет. Я убрал хулиганство в /etc/init.d/rc и добавил аналогичную строку в последний загрузочный скрипт, который называется stop-bootlogd (в /etc/init.d/rc2.d он фигурирует под именем S99stop-bootlogd , то есть запускается последним).

Разумеется, после скачивания я получил чистый каталог.

Помня, что иногда каталог в конечном итоге монтируется, и речь, скорее всего, идет о «состоянии гонки», я добавил сумасшедший сон 360 перед ls. Через 6 минут чаепития я обнаружил, что каталог все еще был смонтирован на момент окончания «сильно замедленной» загрузки.

Потом стал уменьшать время: 60, 45, 30, 20, 10, 5 секунд - файлы были стабильны.

Причем файлы были там даже при сне 1, а когда удалили, скорее всего нет. (На этом этапе я сделал 20 перезагрузок, но получил достоверные результаты - 10 из 10 спящих 1 давали смонтированный каталог, 8 из 10 перезагрузок без сна давали пустой каталог.

То есть состояние гонки было очень тонким.

На одном из форумов Ubuntu (да, я потратил около 15 минут на поиск различных ключевых слов, в основном вокруг слов nfs, rc.local, boot) обсуждалась эта проблема, и там же появилось решение в виде сна (но уже в самом файле rc.local).

Глубже и глубже На этом можно было бы успокоиться, если бы не внутреннее недовольство столь шаманским методом затыкания непонятности.

Я вспомнил, что когда регистрировал зависимость $mountnfs, я открывал файл /etc/init.d/mountnfs.sh (чтобы скопировать содержимое строки Provides).

И было описание:

 
 # Short-Description: Wait for network file systems to be mounted
 # Description:       Network file systems are mounted by
 #                    /etc/network/if-up.d/mountnfs in the background
 #                    when interfaces are brought up; this script waits
 #                    for them to be mounted before carrying on.

Для меня это краткое описание содержало много важных открытий: 1) NFS монтируется в фоновом режиме, асинхронно, то есть параллельно с основной загрузкой.

То есть между процессом монтирования NFS и процессом загрузки возникает состояние гонки.

2) Этот скрипт должен гарантировать, что все общие ресурсы NFS смонтированы во время его выполнения (он был вызван ближе к концу уровня выполнения «S»).

И он этого не делает. Тогда я обратился к мануалу mount.nfs, где было написано следующее - опция bg монтируется в фоновом режиме (насколько я могу судить, эта возможность появилась в сжимании, так как в мануале lenny ничего подобного не упоминается), и опция fg монтируется в синхронном режиме.

Очевидным решением является добавление fg в список параметров монтирования NFS в файле /etc/fstab. Бинго? Перезагрузка.

Нет. Не помогло.

В тот момент мне хотелось все отправить, поставить сон 5 и не волноваться, потому что время приближалось к полуночи, и мелкая проблема вдруг переросла во вполне, почти научное исследование.

Но спортивный интерес все равно остался.

Я посмотрел в Mindmap (к этому моменту я уже осознал проблему как «проблему» и из хаотичных заметок перешел на Mindmap) описание из mountnfs.sh и сосредоточился на фразе «монтируется /etc/network/if-up».

d/mountnfs " Я вник в этот сценарий.

Был скудный комментарий:

 
 # Using 'no !=' instead of 'yes =' to make sure async nfs mounting is
 # the default even without a value in /etc/default/rcS

У нас есть файл /etc/default/rcS? (В Debian настройки скрипта из init.d хранятся в /etc/default, но было несколько неожиданно, что там же хранились и настройки уровня запуска, а не файл).

В этом файле было несколько строк, но ничего интересного, кроме одного:

 
 For information about these variables see the rcS(5) manual page.

У нас есть инструкция! И там натыкаюсь на описание опции:

ASYNCMOUNTNFS Set this to 'no' to disable asynchronous mounting of network drives when the network interfaces are mounted, and instead do it only once when the machine boot. The default is 'yes'.

It is useful to disable this on machines with the root file system in NFS until ifup from ifupdown work properly in such setup.

Бинго? Бинго! Бинго! Банзай.

Радостно записываем в файл /etc/default/rcS строку «ASYNCMOUNTNFS=no», перезагружаемся… .

и снова загребаем точно такие же проблемы.

Я вернулся в /etc/network/if-up.d/mountnfs, где быстро нашел функцию, которая выполнялась, когда для параметра ASYNCMOUNTNFS было установлено значение «нет»:

 
 exit_unless_last_interface() {
     grep "^[:space:]*auto" /etc/network/interfaces  | \
         sed -e 's/[ \t]*auto[ \t]*//;s/[ \t]*$//;s/[ \t]/\n/g' | \
         while read i; do
         if [ `grep -c $i /etc/network/run/ifstate` -eq "0" ]; then
             msg="if-up.d/mountnfs[$IFACE]: waiting for interface $i before doing NFS mounts"
             log_warning_msg "$msg"
             # Can not pass this as a variable because of the while subshell
             mkdir /var/run/network/mountnfs_earlyexit 2> /dev/null
         fi
     done
     if [ -d /var/run/network/mountnfs_earlyexit ]; then
         rmdir /var/run/network/mountnfs_earlyexit 2>/dev/null
         exit 0
     fi
 }

Обратите внимание на вторую строку.

Греп.

И о чем мы ругаемся? Правильно, строка с «авто».

Подождите, но установщик Debian. Да, именно так, вместо опции auto (в файле /etc/network/interfaces) он использует опцию горячего подключения, которая позволяет включать/выключать интерфейс на идти.

Решение Другими словами, поскольку при установке по умолчанию интерфейс eth0 прописан не в auto, а прописан в горячее подключение, то скрипт не ждет готовности этого интерфейса к монтированию и мы получаем состояние гонки не между nfs и rc.local процесс монтирования, а между готовностью сетевого интерфейса и процессом монтирования.

Понятно, что упорный NFS повторно отправит пакет, если с первого раза он не удался.

Но сразу это не сделает. С учетом того, что речь шла об оптике - пока модуль обнаружит SFP+, пока он инициализируется, пока там появится физический канал.

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

Итак, ставим интерфейс в /etc/network/interfaces на auto, перезагружаемся и, ура, шарик появляется вовремя.

Еще раз, еще и еще.

12 из 12. Проблема решена.

Исправляем rc.local на месте, всё работает. Примерно в половине второго ночи добрые охранники закрыли ворота, и мне пришлось стучать минут 10, чтобы меня пустили в машину.

Но оно того стоило.

Мораль Мораль 1: магии и Бога не существует. Если вы столкнулись со странным поведением, ему всегда есть рациональное объяснение, возможно, с иррациональной мотивацией (баг).

Мораль 2: найдя истинную причину проблемы, можно придумать более надежный обходной путь, чем построенный по научной модели (вроде работает, окей).

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

Именно из таких знаний формируются по-настоящему глубокие знания в профессии.

Для себя я изучил, как именно монтируются общие ресурсы NFS из /etc/fstab, выяснил, что существует файл /etc/default/rcS, уточнил точный список используемых в Debian уровней запуска (знал, что они существуют, знал, что такое это было и как этим пользоваться, но так, чтобы точно отбарабанить, какие уровни после каких идут - нет Теперь - да).

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

При этом, чем лучше (и по существу) вы опишете проблему, тем больше вероятность, что она будет решена.

Согласитесь, что заявление об ошибке в конкретной функции с объяснением, почему и при каких обстоятельствах звучит гораздо лучше, чем фраза «NFS не монтируется в момент выполнения rc.local».

Теги: #linux #Системное администрирование #nfs #nfs #boot #racecondition