Pull to refresh

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

Reading time 7 min
Views 8.4K
Буквально вчера мне пришлось разбираться с одним очень тонким и специфичным багом. Баг оказался фичей, которая спотыкалась о другой баг. В ходе изучения проблемы я был вынужден изучить несколько особенностей Debian, угробить 4 часа времени и получить массу опыта.

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

Предыстория

В ходе разворачивания стенда для экспериментов из нескольких идентичных серверов захотелось иметь возможность запускать нужные версии приложения без ручной работы по обновлению кода на куче хостов. Было решено запускать нужные программы с NFS-шары. Приложения были internal use only, одноразовые, причём написанные под конкретную задачу. Шара монтировалась в каталог /opt при загрузке и приложения оттуда запускались с помощью скрипта rc.local. Поскольку речь шла про экспериментальный стенд с очень частым изменением кода, играть в честного разработчика (пакеты, репозиторий, обновления, init.d скрипты) было лениво. Всё происходило под Debian Squeeze.

Шара была прописана в /etc/fstab, запуск нужных тестов — в rc.local. Казалось бы, всё сделано.

… И тут я наткнулся на Мистику. Приложения стартовали раз из пяти, причём версия «кривое приложение» была отметена почти сразу — ровно так же иногда не запускались любые другие исполняемые файлы. Причём, с /opt. Из других каталогов отрабатывали нормально. При этом руками rc.local запускаешь — 100% всё хорошо. При загрузке — успешный запуск раз из пяти, или даже реже.

В начале я не воспринимал эту проблему как серьёзную, и пытался её решить нахрапом. Поскольку проблема проявлялась только для /opt я дописал в rc.local команду ls -a1 /opt >/var/log/ls. Как и предполагалось, в /opt на момент выполнения rc.local было только два файла — точка и две точки. Другими словами, NFS-шара не подмонтировалась. Иногда. А иногда подмонтировалась.


Очевидно, что ситуация «иногда подмонтирована, иногда нет» (при том, что после логина я видел шару подмонтированной всегда) означает ровно одно — race condition между монтированием шар и запуском rc.local.

Начинаем решать


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

Это помогло. По смешному стечению обстоятельств аж на две последовательные перезагрузки. Потом всё продолжилось как было — иногда успех, чаще нет.

Я удивился, ведь nfs-шары монтируются на S runlevel, а rc.local запускается на втором runlelvel (то есть позже 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) указывает на start (kill), число позволяет упорядочить порядок запуска скриптов.

Так вот, в самом конце /etc/init.d/rc я прописал очередной ls. Перезагрузился. Обнаружил в логе три комплекта вывода ls (один выполнился при шатдауне, два при старте — это уровни 'S' и '2'). Удивительно, но последние два были пустыми. То есть на момент окончания выполнения скриптов перехода на runlevel 2 шара всё ещё не примонтирована! Другими словами, система зависимостей скриптов, порядок запуска и т.д. не играет никакой роли — на момент окончания загрузки шары нет.

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

Разумеется, после загрузки я получил чистый каталог. Помня о том, что иногда каталог таки оказывался подмонтирован, и речь идёт вероятнее всего о «гонке условий» (race condition) я добавил перед ls сумасшедший sleep 360.

Через 6 минут чаепитий я обнаружил, что каталог на момент окончания «сильно тормознувшейся» загрузки таки подмонтирован. Дальше я начал сокращать время: 60, 45, 30, 20, 10, 5 секунд — файлы стабильно были. Более того, файлы были даже при sleep 1, но при его удалении — с большой вероятностью нет. (В этом месте я сделал 20 перезагрузок, но получил достоверные результаты — 10 из 10 sleep 1 давали подмонтированный каталог, 8 из 10 перезагрузок без sleep давали пустой каталог. То есть race condition был очень тонкий.

На каком-то из форумов убунты (да, я потратил минут 15 на поиск по различным ключевым словам, в основном в районе слов nfs, rc.local, boot) эта проблема обсуждалась, и там тоже фигурировало решение в виде sleep (но уже в самом файле 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 монтируется в бэкграунде, асинхронно, то есть в параллель с основной загрузкой. То есть race condition идёт между процессом монтирования NFS и процессом загрузки.
2) Этот скрипт должен обеспечить подмонтирование всех шар NFS в момент своего выполнения (он вызывался ближе к концу 'S' runlevel). И он этого не делает.

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

Очевидное решение — добавить fg в список опций монтирования NFS в /etc/fstab. Bingo? Перезагрузка… Нет. Не сработало.

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

Я посмотрел в mindmap'е (к этому времени я уже признал проблему «проблемой» и из хаотичных заметок переключился на mindmap) на описание из mountnfs.sh и сфокусировался на фразе «mounted by /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? (В дебиане настройки скриптов из init.d хранятся в /etc/default, но было несколько неожиданно, что там же хранилась настройка не файла, а runlevel'а).

В этом файле было несколько строчек, но ничего интересного, кроме одного:
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 стоит в 'no':
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
}

Внимание на вторую строчку. Grep. И что же мы грепаем? Правильно, строчку с 'auto'.

Стоп, но ведь инсталлятор дебиана… Да, совершенно верно, вместо опции auto (в файле /etc/network/interfaces) он использует опцию hot-plug, которая позволяет включать/выключать интерфейс на ходу…

Решение


Другими словами, так как на дефолтной установке интерфейс eth0 не записывается в auto, а записывается в hot-plug, то скрипт не ждёт готовности этого интерфейса к монтированию и мы получаем race condition не между процессом монтирования nfs и rc.local, а между готовностью сетевого интерфейса и процессом монтирования. Понятно, что упорный NFS перепошлёт пакетик повторно, если с первого раза не удалось. Но сделает он это далеко не сразу… С учётом, что речь шла про оптику — пока модуль обнаружит SFP+, пока тот проинициализируется, пока там physical link появится… Реально это можно глазками увидеть — процесс не сильно быстрый, и при некоторых обстоятельствах sleep 1 могло и не хватить…

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

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

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

Мораль


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

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

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

Мораль 4: а ещё можно послать багрепорт и решить эту проблему самым правильным методом — устранить проблему. При этом, чем лучше (и по сути) вы опишете проблему, тем больше вероятность, что её решат. Согласитесь, что заявление об ошибке в конкретной функции с объяснением почему и при каких обстоятельствах, звучит куда лучше, чем фраза «NFS не подмонтирована в момент выполнения rc.local».
Tags:
Hubs:
+157
Comments 78
Comments Comments 78

Articles