Среди всех служебных обязанностей системного администратора, самой интересной, сложной и продуктивной, на мой взгляд, является детективная работа по мотивам случившегося «инцидента». При этом, в отличие от реальной криминологии, системный администратор сам себе одновременно и детектив, и эксперт по вещественным доказательствам.
Я сейчас исключаю из рассмотрения инциденты с осмысленным злым умыслом, это отдельный топик. Речь про стихийные проблемы (сервер упал/завис, виртуальная машина начала тормозить а потом перестала, приложение потеряло 100500 транзакций и считает, что всё хорошо).
Иногда она тривиальная («самопроизвольно перезагрузился сервер», или «упал самолёт»). Иногда она крайне трудная для объяснения («клиенты жалуются что у не получается поменять регион», при этом все сотрудники с клиентскими аккаунтами регион поменять могут). Чаще всего, чем дальше от системного администратора источник жалобы, тем более размытой становится жалоба: «клиент говорит, что после заказа в интернет-магазине плюшевого медведя он не может поменять регион на IE7 при использовании LTE-коннекта через USB-модем, а ещё он получает 500ую ошибку при попытке отменить операцию и нажатии „назад“).
Ещё более сложным является случай, когда несколько проблем сливаются вместе: „сервер внезапно перезагрузился, а на другом сервере был таймаут работы с базой данных, а клиенты в это время писали, что у них не грузятся картинки“. Сколько тут проблем? Одна, две, три, а может и больше? Какие из проблем надо молча объединить (база данных и отсутствие картинок), а какие надо учитывать раздельно? А если в этот момент ещё придёт жалоба, что пользователь не может залогиниться в систему — это обычное „забыл пароль“ или тоже симптом? А если таких пользователей два? Или кто-то мимоходом говорит, „что-то у меня почта не проходит“?
Подсознательно в момент начала проблем, каждая новая жалоба тут же объединяется с существующими (и может завести не туда), плюс резко увеличивает стресс из-за того, что приходится думать не о трёх симптомах, а о восьми, например. А в голове хорошо только семь удерживаются. Но в то же время в моей практике бывало так, что пришедший „новый“ симптом с лёгкостью приводил к сути проблемы и её устранению…… за вычетом того, что серьёзная проблема (с которой всё началось) не имеет никакого отношения к радостно и быстро починенной ерунде. А время потрачено.
Простого совета для такой ситуации нет. В сложных ситуациях я обычно выписываю всё, что слышу и замечаю, не анализируя, но фиксируя время.
То есть журнал (в sticky notes) выглядит так:
Не стоит увлекаться (не время печатать), но симптомы стоит выписывать. Один это случай или несколько, важные это симптомы или нет, станет понятно потом. Я обычно начинаю выписывать примерно после третьего отвлекающего обращения.
Вторым аспектом проблемы является доказательство существования проблемы. Самая ненавистная фраза, которой не удаётся избежать:
Поиск проблемы чаще всего сложнее её устранения. Худший сценарий, который можно себе представить — поток жалоб от пользователей при совершенно зелёненьком мониторинге. Более того, иногда бывает так, что глазками/ручками смотришь — всё хорошо. А жалобы есть. То есть „проблема есть“, „но проблемы нет“. Это самое отвратительное состояние и если речь идёт не о примитивном „работает“/»не работает", а о более тонких вещах, то при неудачном стечении обстоятельств, оно может тянуться неделями или даже месяцами. Реальный пример из моей практики: раз в три-пять месяцев возникает задержка в 300-400с (!) при рядовой нагрузке на дисковый массив. Никаких других симптомов нет. В лаборатории не проявляется. Отлаживай как хочешь.
Так что удивительно, но испытываешь радость, научившись достоверно воспроизводить проблему. Реальный пример: В своё время у меня ушло больше года на формулирование сценария зависания enclosure с SATA-дисками. В продакшене я такую гадость наблюдал, но воспроизвести на стенде или синтетической нагрузке не мог. Наконец, сумел, чистой случайностью. К позору компании LSI, реакции на багрепорт не последовало до сих пор, но по крайней мере, у меня появился железобетонный аргумент в обсуждении (не)применимости enclosure под серьёзными нагрузками. Надо сказать, эквивалентного сценария для SAS-дисков у меня нет до сих пор, хотя есть крайне высокая уверенность, что проблема воспроизводима с тем же успехом. Так что можно сказать, что за 8 лет я такой же баг, но c SAS, так и не научился достоверно воспроизводить.
Ещё одной бедой того же плана является взаимодействие отделов. Когда нет очевидного воспроизводимого доказательства, жаловаться на туманные боли и глюки очень тяжело — ведь человек видит, что «у него всё работает». На доверии человек может сделать сколько-то телодвижений по проверке и отладке, но когда ему всё время видно, что всё хорошо, то слова со стороны «на самом деле всё плохо» стремительно теряют авторитетность. С этим можно и нужно бороться, но феномен этот есть и является объективным. Его надо пресекать у окружающих и сдерживать в себе самом, если кто-то другой жалуется на проблемы.
Ещё одной серьёзной дилеммой является выбор между «чинить» и «изучать».
Оно не работает. А должно. Надо чинить. Прямо сейчас. К сожалению, починка часто уничтожает все доказательства и обстоятельства (например, из-за перезагрузки сервера теряется состояние ядра, процессов и содержимое tmpfs). Так что если есть возможность, надо переводить нагрузку на работающие сервера и избавляться от цейтнота не избавляясь от доказательств.
Это мой любимый режим работы. Когда проблема локализована, исключена из продакшена (из его чувствительных мест), но не устранена. Можно внимательно и нежно пощупать во всех местах, почувствовать проблему точнее, понять её масштабы, изучить обстоятельства и все прямые симптомы, выписать все характерные строчки из всех консолей и описать поведение для себя и потомков. После того, как пациент отжат и разглажен, его можно попытаться починить, причём начинать надо с наименее интрузивных методов и переходить к более суровым, если менее суровыми не удалось. На выходе это даст максимальное соотношение experience/incident.
После того, как причина найдена («самолёт упал из-за того, что у него перестали работать моторы») и устранена («заменили самолёт, после перезапуска полёт нормальный, от новых пассажиров жалоб не поступает, саппорт отвечает на жалобы и просьбы опознания трупов предыдущих пассажиров в штатном режиме»), возникает некий червячок сомнения: а точно ли причина установлена? Чем сложнее инсталляция, чем больше в ней связей между компонентами, чем менее очевидным и детерминированным является состояние каждой из них, тем менее однозначной становится связь между предполагаемым следствием и предполагаемой причиной. Вопрос: «а почему моторы перестали работать?». Читая логи нагиоса в кабине пилота, находим ответ: «потому что в них не поступало топливо». Двигатели плохие? Нет, вроде бы, всё правильно делали. Нет топлива — нет тяги. Отчёт о проишествии начинает выглядеть более осмысленно: «в двигатели перестало поступать топливо, они остановились и самолёт упал. Система резервирования пилотов в кабине не сработала (причины выясняются)».
Насколько глубоко надо идти в попытках понять «почему?». Каждый последующий шаг открывает очередную бездну (изучение большинства тонких проблем связано с чтением исходного текста), это сильно выматывает и занимает много времени. Есть даже такая (увы, не шуточная) пословица: «Сегодня я узнал ещё одну вещь, которую мне не надо было знать». Обычно это происходит после чтения очередного шедевра индусской мысли.
Живой пример. Есть такой монстр виртуализации — XenServer. Могучая корпорация (Citrix), энтерпрайз, миллионные продажи, тысячедолларовые лицензии, всё чин-чинарём.
… Пока старый измученный сисадмин не обнаруживает в коде, обслуживающим диски виртуальных машин вот такую конструкцию: запуск программы ls в python и парсинг её вывода для получения списка файлов в директории. Ещё одна вещь, которую ему хочется развидеть.
Каждый шаг в прошлое требует, во-первых, более глубокого понимания как очередная компонента работает, а, во-вторых, всё большей широты охвата. Потому что чаще всего каждый шаг в прошлое — это поиск суперпозиции от воздействия всё большего числа компонент, часто выходящих за область обычного исследования, и в каждой из них надо глубоко порыться.
Иногда там «черепахи до самого низа» — то есть широта поиска становится слишком большой, объём того, куда надо смотреть — слишком обширным, а логов становится всё меньше (и они всё менее релевантны). В этом случае поиск затыкается из-за возрастающей сложности анализа и нехватки ресурсов (времени/энтузиазма).
А бывает так, что ответ найден на самом дне. Если кто не читал предыдущий рассказ, хороший пример: Админские байки: в погоне за фрагментацией туннелей в оверлейной сети.
Но бывает и третий вариант: когда «поломавшее изменение» найдено, но вопросы остались. Например: «зачем?» (обычно звучит его матерный эквивалент). При том, что процесс начинает напоминать экзистенциальный поиск светоча разума в человечестве, вопрос на самом деле важный. Это может быть глупость, небрежение, ошибка. Но если нет?
И тогда разворачивается ещё один слой вопросов: а почему они (разработчики) хотят делать так, как у нас работать не будет? Понятно, что это они (разработчики) негодяи и злодеи, а мы (сисадмины) — все принцы на белых конях. Но если нет? Что, если мы его готовим не так?
Это, в свою очередь, может привести к серьёзному пересмотру архитектуры. Мелкая редкая проблема, частность, внезапно, обнажает логическую противоречивость, или нарушение обещаний/ожиданий от компонентов. (Замечание: «поправить и забыть» не даёт возможности увидеть как раз такие штуки). Реальный пример: при «живой» миграции виртуальной машины иногда, крайне редко, она (миграция) отваливалась с ошибкой 0x4c (без дальнейших пояснений). И оставляла виртуальную машину в нерабочем состоянии посреди миграции. После проклятий на головы разработчиков, составления регламентов миграции машин и прочей чепухи, однажды, во ремя одного из зависаний залезли глубоко в систему и начали изучать «недомигрировавшую» машину. Обычно машина чинилась методом перезапуска, а тут появился шанс внимательно изучить, т.к. машина была «своя» и можно было её оставить в этом состоянии надолго. В результате пристального анализа событий из логов, было выяснено, что если память виртуальной машины менялась в большую сторону после того, как машина начала мигрировать, но до определённого момента (окно примерно в 2с), то гипервизор застревал на невозможности скопировать остаток памяти. Виноваты программисты? Ну, да, чуть-чуть. Надо было думать о подобном. Виноваты ли архитекторы итоговой системы? Виноваты, и больше, чем программисты. Нечего переходные процессы в середине миграции устраивать. Небольшое исправление, отключавшее регуляцию памяти на время миграции, и ошибки «4c» больше не стало.
Возвращаемся к детективной метафоре.
Чем больше серверов в хозяйстве, тем сложнее становится с определением «места». Если у вас в хозяйстве одинокий сервер, то что бы не случилось (кроме пропадания электричества/интернета/холода), все проблемы — на Сервере. Одном и единственном. Если у вас в хозяйстве несколько серверов, картинка уже может стать сложнее, но не радикально. Можно изучить все сервера по-очереди и найти «место преступления».
Но если серверов несколько тысяч?
Предполагается, что этому моменту хотя бы понятно, что происходит. Дальше надо понять workflow происходящего. В сложных системах он может быть очень запутанным (придумывая на ходу: LB/CDN/кешер/application-сервер/база данных. БД — это несколько серверов, и надо понять мастер или какой-то из slave'ов, application'ы могут ходить на другие сервера, CDN в свою очередь может быть завязан на объектное хранилище (+несколько десятков серверов) или СХД). Бывает так, что некоторые API-запросы пробивают через несколько application'ов и вообще терминируются за пределами серверов (IPMI, коммутаторы, запросы к инопланетянам за рандомом через HWRNG и т. д.).
Так вот, workflow можно разбирать в обратном порядке (от результата), или по наитию, от предполагаемой причины.
В обратном порядке — это занудный, но точно работающий метод. Идём на load balancer или его логи, смотрим куда уходят/уходили запросы, идём на кешер, смотрим кешировано или нет, идём на соответствующий application, смотрим какое приложение, смотрим логи, смотрим в какую БД и на какой сервер, смотрим логи БД, находим, что лог засран ошибками, happy end). Долго. Десятки сложных запросов в систему сборки логов, сотни килобайт из которых надо выковырять нужное и т.д.
Есть другой подход — интуитивный. «Что-то мне это напоминает по поведению… На БД не похоже, наверное, это новое приложение хулиганит» — и идём читать (произвольно выбранные интуицией) логи. При всей произвольности выбора, опыт и интуиция, способные по второстепенным, но важным признакам понять где проблема, часто оказываются правы. Во второстепенных признаках может быть совершенно неожиданные вещи — например, время (3:59? cron.daily на БД?), специфичное форматирование страницы об ошибке (странно выглядит. Стили не полностью подгрузились? Смотрим бэкэнд у серверов со статикой), особенности сообщения (если в сообщении пробивается формат strerr, то копать надо сразу на хост, где это выполнялось, а если напоминает трейс питона/явы, пусть даже фрагментарно, то лучше читать в районе приложения), латенси при ответах (что-то мне не нравится как оно по ssh дёргается, хватит читать логи пошли отлаживать сеть), интервалы между флаппингом (флаппинг — когда сервис меняет состояние между «работает» и «не работает») — кажется, это оркейстрейшен хулиганит…
Я обычно делаю две-три попытки найти с помощью интуиции, после чего сваливаюсь на медленный путь. Иногда, когда в процессе кажется, что «всё понял», могу прыгнуть вперёд, но в общем случае приходится раскручивать до нужного места.
При всей тривиальности ОТО, в пространственно-временном континууме, а так же в администрировании серверов, время совершенно не тривиальная вещь для установления. Во-первых, не все события имеют время. Например, приложение начало писать судорожные буквы в неожиданный лог файл. Буквы важные, но таймстемпа не имеют (и лог в logstash не уходит, потому что никто не думал, что такой лог (в /tmp) быть может). Или, время есть, но очень крупными мазками. Например, по atop'у видно, что приложение завершилось между 12:20 и 12:30. Грубовато.
Иногда бывает так, что для правильной последовательности, нужно синхронное время с разных серверов с точностью меньше секунды. Потому что это важно — сначала запрос, а потом трейс, или же сначала трейс, а потом неответ на не связный с аварией запрос.
А субсекндная точность — это уже совсем сурово. Во-первых ntp может чуть-чуть гулять. Реальный пример из практики: в мрачные времена openvswitch 1.1 у него была дурная привычка добавлять большую (случайную) latency на новые flow (и жрать память до одури, но это отдельный рассказ). И был ntp на всех хостах. И удумал ntp, что джиттеринг большой. И начало время на хостах медленно расходиться, не мало ни много — на 30-90 секунд. Это при том, что все синхронизировались с одного сервера в локалке с пингом в 0.0001с. Итогом стала отдельная проверка для нагиоса, что время на серверах не расходится.
Во-вторых, логгинг может ставить timestamp пост-фактум (для тяжёлых трейсов это может быть много). Ещё веселее, когда одна из жертв возникшей проблемы — ntpd, или даже просто время на сервере. В моей практике как-то было, что программа попутала время (и перестала принимать подписанные сообщения). Forensic показал, что расходится время записи в лог-файл с временем модификации файла, что и стало ключевым для обнаружения бага (возникавшего на стыке летне-зимних часовых поясов).
Бывает так, что разные источники вообще не имеют общего ntp или имеют очень приблизительное представление о времени (саппорт два часа назад сказал, что пять минут назад клиент сказал, что десять минут назад всё упало).
В таких условиях, когда в голове хронологию не удержать, приходится опять же выписывать, на этот раз хронологическую последовательность.
Программы никогда не делают ничего просто так. Особенно, в районе всяких плохих ветвлений. Почему программа зависла на выходе? Почему ядро не отдало IO обратно? Почему лог не записался?
Для каждого субъекта действия надо выписать его мотив. Зачем? Почему? Если мотива нет, но есть подозрение на участие, надо хотя бы выписать, что делал и что должен был делать.
В идеальном мире программы не содержат ошибок, в реальном мире — содержат и годами работают с ними. При этом многие ошибки «лежат тихо и ни кого не трогают» в редких уголках кода, пока не случается так, что наступает их очередь. Бывает, починка состоит не в том, чтобы найти и исправить ошибку, а в том, чтобы устранить обстоятельства, вызывающие соответствующий кусок кода. При этом и режим «с ошибкой», и режим «без ошибки» — оба являются более-менее штатными. Наиболее ярким примером такого (не в моей практике) является достижение порога в 512к префиксов в full view в BGP у некоторых старых маршрутизаторов (подробнее).
Ещё один важный вопрос: а кто участвует в создании аварийной ситуации? Часто оказывается, что виновником является не только прямой подозреваемый. Из практики: запрос для биллинга не смог отработать. Взгляд показал, что mongodb, хранящая временные самплы, не запущена. Цейтнот потребовал «всё перезапустить», то есть состояние процессов было утеряно. Последующие разбирательства показали, что mongo постоянно завершается (запись в dmesg). При этом никаких OOM'ов. Зато после нескольких минут исследования невнятных логов оказалось, что mongodb достаточно культурно завершается само по нехватке памяти для ответа на сложный запрос.
А логи atop'а показали, что рядом пухнет ceilometer-collector, поджимая и поджимая монгу по памяти. Не было бы atop'а, никто бы ничего не догадался, ибо его перезапустили вместе с mongo. Хотя монга тоже виновата, ибо не написала ясно, что ей не нравится.
Часто бывает так, что неожиданность в одном процессе — это ошибка. Но вызвана она другой причиной, часто совсем несвязной.
Бывает так, что нарушается предположение о stateless-поведении системы. Все думают, что повторный запуск на тех же данных даёт те же самые результаты, а в реальности оказывается, что первый запуск и последующие — две большие разницы. При этом авария возникает на первом старте, а после перезапуска всё проходит и работает как положено.
Ещё серьёзнее цепочка отладки становится, если источником проблемы являются данные в БД. Откуда они? Данные могут лежать долго-долго, пока о них споткнётся код. Пример из свежей практики: ceilometer начал падать на метаданных образа с точкой в имени. Образ взял метаданные во время создания снапшота инстанса. А инстанс взял метаданные с хоста, где был запущен (в прошлом году). А метаданные с опечаткой уже давно были поправлены. А проблема укусила через год.
Выстраивание таких цепочек — самая увлекательная часть процесса. В этот момент все связи в системе, под пристальным взглядом подозревающего детектива становятся кристально видны, и часто ужасают своей ненужностью (после того как оно сломалось, становится понятно, как плохо это было). Простой пример из практики: по молодости было принято залихватское решение: сделать на группе однотипных серверов nfs-шару с временными файликами/однострочниками. Это очень удобно, потому что часто файлик с одного сервера нужен на другом, и иметь их в одном месте очень удобно. Так было до тех пор, пока не возникли проблемы на сервере, где была nfs. После ребута… Да, внезапно, оказалось, что path включает в себя этот каталог, и попытка вызывать любую программу приводит к скану nfs-шары.… На этапе логина. В тот раз прорвались через ssh /bin/bash -i. С тех пор я от практики такой шары не отказался, но в path её больше не прописываю.
Процесс разбирательства в причинах часто же позволяет внезапно и очень глубоко понять происходящее в системе с точки зрения архитектуры. Потому что когда всё работает, оно воспринимается как данность. А когда нет… Вот тогда-то и становится понятно, как оно друг с другом связано, как оно работает, а как нет.
В каком-то смысле у меня нет ощущения, что я чувствую, как работает система, пока я не посмотрел, как она ломается. Потому что именно в момент частичной поломки становятся видны все ошибки проектирования, неудачные решения и отсутствие запаса прочности. Ломается всё, вопрос в том, с какими последствиями. Одно решение при фатальной ошибке проинформирует о ней и завершится, а другое обнаружит себя в ветке кода, где обработка ТАКИХ ошибок не предусмотрена, с последствиями соответствующего масштаба.
Его написание — обязательная часть forensic. Память у людей плохая, особенно на нелогичные и плохоструктурированные данные. Заключение делится на четыре части: характерные признаки (особенно, цитаты из логов), описание сути произошедшего, метод ранней (или хоть какой-то) диагностики — чаще всего, ещё одна проверка в мониторинг, и рекомендации по устранению. Всё это выписывается в вики (у вас же есть корпоративная вики, правда?), и раскидывается как набор задач для выполнения. Тут есть ещё одна плохая тенденция, с которой надо бороться: «никогда такого не было и снова опять не будет». Если случилось что-то странное, то его не надо игнорировать. Мониторинг, мониторинг, мониторинг. Плюс выписывание всего, что было. Бывает так, что пара-тройка крайне редких (однократных) инцидентов внезапно выстраивается в стройную картинку много позже.… Если фрагменты картинок сохранились. Так что не лениться выписывать, не лениться разбирать, и покрывать тестами.
Я сейчас исключаю из рассмотрения инциденты с осмысленным злым умыслом, это отдельный топик. Речь про стихийные проблемы (сервер упал/завис, виртуальная машина начала тормозить а потом перестала, приложение потеряло 100500 транзакций и считает, что всё хорошо).
Суть происшествия
Иногда она тривиальная («самопроизвольно перезагрузился сервер», или «упал самолёт»). Иногда она крайне трудная для объяснения («клиенты жалуются что у не получается поменять регион», при этом все сотрудники с клиентскими аккаунтами регион поменять могут). Чаще всего, чем дальше от системного администратора источник жалобы, тем более размытой становится жалоба: «клиент говорит, что после заказа в интернет-магазине плюшевого медведя он не может поменять регион на IE7 при использовании LTE-коннекта через USB-модем, а ещё он получает 500ую ошибку при попытке отменить операцию и нажатии „назад“).
Ещё более сложным является случай, когда несколько проблем сливаются вместе: „сервер внезапно перезагрузился, а на другом сервере был таймаут работы с базой данных, а клиенты в это время писали, что у них не грузятся картинки“. Сколько тут проблем? Одна, две, три, а может и больше? Какие из проблем надо молча объединить (база данных и отсутствие картинок), а какие надо учитывать раздельно? А если в этот момент ещё придёт жалоба, что пользователь не может залогиниться в систему — это обычное „забыл пароль“ или тоже симптом? А если таких пользователей два? Или кто-то мимоходом говорит, „что-то у меня почта не проходит“?
Подсознательно в момент начала проблем, каждая новая жалоба тут же объединяется с существующими (и может завести не туда), плюс резко увеличивает стресс из-за того, что приходится думать не о трёх симптомах, а о восьми, например. А в голове хорошо только семь удерживаются. Но в то же время в моей практике бывало так, что пришедший „новый“ симптом с лёгкостью приводил к сути проблемы и её устранению…… за вычетом того, что серьёзная проблема (с которой всё началось) не имеет никакого отношения к радостно и быстро починенной ерунде. А время потрачено.
Простого совета для такой ситуации нет. В сложных ситуациях я обычно выписываю всё, что слышу и замечаю, не анализируя, но фиксируя время.
То есть журнал (в sticky notes) выглядит так:
- Мониторинг сработал на srv1 (22:05)
- (имя) сказал про проблемы с почтой (22:07)
- Не могу залогиниться на srv12 (22:08)/refused — Зашёл 22:16, dmesg чисто, аптайм большой
- Не могу залогиниться на srv13 (22:10) (timeout) — отвалился офисный wifi (22:11)
- Не открывается панель (22:12)
- Саппорт пишет, что клиент жалуется, что ничего не работает, 22:15
Не стоит увлекаться (не время печатать), но симптомы стоит выписывать. Один это случай или несколько, важные это симптомы или нет, станет понятно потом. Я обычно начинаю выписывать примерно после третьего отвлекающего обращения.
Вторым аспектом проблемы является доказательство существования проблемы. Самая ненавистная фраза, которой не удаётся избежать:
У меня всё работает
После того, как Энийские Авиалинии пожаловались производителю на то, что самолёты иногда падают, разработчик проверил, что самолёты взлетают/садятся и закрыл тикет с 'Unable to reproduce'. Сотрудники поддержки Энийских Авиалиний продолжают собирать статистику по падению самолётов и пытаются научиться воспроизводить падение в лабораторных условиях.
Поиск проблемы чаще всего сложнее её устранения. Худший сценарий, который можно себе представить — поток жалоб от пользователей при совершенно зелёненьком мониторинге. Более того, иногда бывает так, что глазками/ручками смотришь — всё хорошо. А жалобы есть. То есть „проблема есть“, „но проблемы нет“. Это самое отвратительное состояние и если речь идёт не о примитивном „работает“/»не работает", а о более тонких вещах, то при неудачном стечении обстоятельств, оно может тянуться неделями или даже месяцами. Реальный пример из моей практики: раз в три-пять месяцев возникает задержка в 300-400с (!) при рядовой нагрузке на дисковый массив. Никаких других симптомов нет. В лаборатории не проявляется. Отлаживай как хочешь.
Так что удивительно, но испытываешь радость, научившись достоверно воспроизводить проблему. Реальный пример: В своё время у меня ушло больше года на формулирование сценария зависания enclosure с SATA-дисками. В продакшене я такую гадость наблюдал, но воспроизвести на стенде или синтетической нагрузке не мог. Наконец, сумел, чистой случайностью. К позору компании LSI, реакции на багрепорт не последовало до сих пор, но по крайней мере, у меня появился железобетонный аргумент в обсуждении (не)применимости enclosure под серьёзными нагрузками. Надо сказать, эквивалентного сценария для SAS-дисков у меня нет до сих пор, хотя есть крайне высокая уверенность, что проблема воспроизводима с тем же успехом. Так что можно сказать, что за 8 лет я такой же баг, но c SAS, так и не научился достоверно воспроизводить.
Ещё одной бедой того же плана является взаимодействие отделов. Когда нет очевидного воспроизводимого доказательства, жаловаться на туманные боли и глюки очень тяжело — ведь человек видит, что «у него всё работает». На доверии человек может сделать сколько-то телодвижений по проверке и отладке, но когда ему всё время видно, что всё хорошо, то слова со стороны «на самом деле всё плохо» стремительно теряют авторитетность. С этим можно и нужно бороться, но феномен этот есть и является объективным. Его надо пресекать у окружающих и сдерживать в себе самом, если кто-то другой жалуется на проблемы.
Ещё одной серьёзной дилеммой является выбор между «чинить» и «изучать».
Чинить
Оно не работает. А должно. Надо чинить. Прямо сейчас. К сожалению, починка часто уничтожает все доказательства и обстоятельства (например, из-за перезагрузки сервера теряется состояние ядра, процессов и содержимое tmpfs). Так что если есть возможность, надо переводить нагрузку на работающие сервера и избавляться от цейтнота не избавляясь от доказательств.
Изучать
Это мой любимый режим работы. Когда проблема локализована, исключена из продакшена (из его чувствительных мест), но не устранена. Можно внимательно и нежно пощупать во всех местах, почувствовать проблему точнее, понять её масштабы, изучить обстоятельства и все прямые симптомы, выписать все характерные строчки из всех консолей и описать поведение для себя и потомков. После того, как пациент отжат и разглажен, его можно попытаться починить, причём начинать надо с наименее интрузивных методов и переходить к более суровым, если менее суровыми не удалось. На выходе это даст максимальное соотношение experience/incident.
Глубина исследования
После того, как причина найдена («самолёт упал из-за того, что у него перестали работать моторы») и устранена («заменили самолёт, после перезапуска полёт нормальный, от новых пассажиров жалоб не поступает, саппорт отвечает на жалобы и просьбы опознания трупов предыдущих пассажиров в штатном режиме»), возникает некий червячок сомнения: а точно ли причина установлена? Чем сложнее инсталляция, чем больше в ней связей между компонентами, чем менее очевидным и детерминированным является состояние каждой из них, тем менее однозначной становится связь между предполагаемым следствием и предполагаемой причиной. Вопрос: «а почему моторы перестали работать?». Читая логи нагиоса в кабине пилота, находим ответ: «потому что в них не поступало топливо». Двигатели плохие? Нет, вроде бы, всё правильно делали. Нет топлива — нет тяги. Отчёт о проишествии начинает выглядеть более осмысленно: «в двигатели перестало поступать топливо, они остановились и самолёт упал. Система резервирования пилотов в кабине не сработала (причины выясняются)».
Насколько глубоко надо идти в попытках понять «почему?». Каждый последующий шаг открывает очередную бездну (изучение большинства тонких проблем связано с чтением исходного текста), это сильно выматывает и занимает много времени. Есть даже такая (увы, не шуточная) пословица: «Сегодня я узнал ещё одну вещь, которую мне не надо было знать». Обычно это происходит после чтения очередного шедевра индусской мысли.
Живой пример. Есть такой монстр виртуализации — XenServer. Могучая корпорация (Citrix), энтерпрайз, миллионные продажи, тысячедолларовые лицензии, всё чин-чинарём.
… Пока старый измученный сисадмин не обнаруживает в коде, обслуживающим диски виртуальных машин вот такую конструкцию: запуск программы ls в python и парсинг её вывода для получения списка файлов в директории. Ещё одна вещь, которую ему хочется развидеть.
… Старший пилот нервно поёжился, вспомнив, что топливный шланг к топливному баку крепится продырявленным презервативом, потому что у бака выходное отверстие 11 мм, а у шланга диаметр — 19. Главное, не думать об этом. Авось пронесёт… Зато дедлайн взлёта не сорвали.
Каждый шаг в прошлое требует, во-первых, более глубокого понимания как очередная компонента работает, а, во-вторых, всё большей широты охвата. Потому что чаще всего каждый шаг в прошлое — это поиск суперпозиции от воздействия всё большего числа компонент, часто выходящих за область обычного исследования, и в каждой из них надо глубоко порыться.
Иногда там «черепахи до самого низа» — то есть широта поиска становится слишком большой, объём того, куда надо смотреть — слишком обширным, а логов становится всё меньше (и они всё менее релевантны). В этом случае поиск затыкается из-за возрастающей сложности анализа и нехватки ресурсов (времени/энтузиазма).
А бывает так, что ответ найден на самом дне. Если кто не читал предыдущий рассказ, хороший пример: Админские байки: в погоне за фрагментацией туннелей в оверлейной сети.
Но бывает и третий вариант: когда «поломавшее изменение» найдено, но вопросы остались. Например: «зачем?» (обычно звучит его матерный эквивалент). При том, что процесс начинает напоминать экзистенциальный поиск светоча разума в человечестве, вопрос на самом деле важный. Это может быть глупость, небрежение, ошибка. Но если нет?
И тогда разворачивается ещё один слой вопросов: а почему они (разработчики) хотят делать так, как у нас работать не будет? Понятно, что это они (разработчики) негодяи и злодеи, а мы (сисадмины) — все принцы на белых конях. Но если нет? Что, если мы его готовим не так?
Это, в свою очередь, может привести к серьёзному пересмотру архитектуры. Мелкая редкая проблема, частность, внезапно, обнажает логическую противоречивость, или нарушение обещаний/ожиданий от компонентов. (Замечание: «поправить и забыть» не даёт возможности увидеть как раз такие штуки). Реальный пример: при «живой» миграции виртуальной машины иногда, крайне редко, она (миграция) отваливалась с ошибкой 0x4c (без дальнейших пояснений). И оставляла виртуальную машину в нерабочем состоянии посреди миграции. После проклятий на головы разработчиков, составления регламентов миграции машин и прочей чепухи, однажды, во ремя одного из зависаний залезли глубоко в систему и начали изучать «недомигрировавшую» машину. Обычно машина чинилась методом перезапуска, а тут появился шанс внимательно изучить, т.к. машина была «своя» и можно было её оставить в этом состоянии надолго. В результате пристального анализа событий из логов, было выяснено, что если память виртуальной машины менялась в большую сторону после того, как машина начала мигрировать, но до определённого момента (окно примерно в 2с), то гипервизор застревал на невозможности скопировать остаток памяти. Виноваты программисты? Ну, да, чуть-чуть. Надо было думать о подобном. Виноваты ли архитекторы итоговой системы? Виноваты, и больше, чем программисты. Нечего переходные процессы в середине миграции устраивать. Небольшое исправление, отключавшее регуляцию памяти на время миграции, и ошибки «4c» больше не стало.
Место проишествия
Возвращаемся к детективной метафоре.
Чем больше серверов в хозяйстве, тем сложнее становится с определением «места». Если у вас в хозяйстве одинокий сервер, то что бы не случилось (кроме пропадания электричества/интернета/холода), все проблемы — на Сервере. Одном и единственном. Если у вас в хозяйстве несколько серверов, картинка уже может стать сложнее, но не радикально. Можно изучить все сервера по-очереди и найти «место преступления».
Но если серверов несколько тысяч?
Предполагается, что этому моменту хотя бы понятно, что происходит. Дальше надо понять workflow происходящего. В сложных системах он может быть очень запутанным (придумывая на ходу: LB/CDN/кешер/application-сервер/база данных. БД — это несколько серверов, и надо понять мастер или какой-то из slave'ов, application'ы могут ходить на другие сервера, CDN в свою очередь может быть завязан на объектное хранилище (+несколько десятков серверов) или СХД). Бывает так, что некоторые API-запросы пробивают через несколько application'ов и вообще терминируются за пределами серверов (IPMI, коммутаторы, запросы к инопланетянам за рандомом через HWRNG и т. д.).
Так вот, workflow можно разбирать в обратном порядке (от результата), или по наитию, от предполагаемой причины.
В обратном порядке — это занудный, но точно работающий метод. Идём на load balancer или его логи, смотрим куда уходят/уходили запросы, идём на кешер, смотрим кешировано или нет, идём на соответствующий application, смотрим какое приложение, смотрим логи, смотрим в какую БД и на какой сервер, смотрим логи БД, находим, что лог засран ошибками, happy end). Долго. Десятки сложных запросов в систему сборки логов, сотни килобайт из которых надо выковырять нужное и т.д.
Есть другой подход — интуитивный. «Что-то мне это напоминает по поведению… На БД не похоже, наверное, это новое приложение хулиганит» — и идём читать (произвольно выбранные интуицией) логи. При всей произвольности выбора, опыт и интуиция, способные по второстепенным, но важным признакам понять где проблема, часто оказываются правы. Во второстепенных признаках может быть совершенно неожиданные вещи — например, время (3:59? cron.daily на БД?), специфичное форматирование страницы об ошибке (странно выглядит. Стили не полностью подгрузились? Смотрим бэкэнд у серверов со статикой), особенности сообщения (если в сообщении пробивается формат strerr, то копать надо сразу на хост, где это выполнялось, а если напоминает трейс питона/явы, пусть даже фрагментарно, то лучше читать в районе приложения), латенси при ответах (что-то мне не нравится как оно по ssh дёргается, хватит читать логи пошли отлаживать сеть), интервалы между флаппингом (флаппинг — когда сервис меняет состояние между «работает» и «не работает») — кажется, это оркейстрейшен хулиганит…
Я обычно делаю две-три попытки найти с помощью интуиции, после чего сваливаюсь на медленный путь. Иногда, когда в процессе кажется, что «всё понял», могу прыгнуть вперёд, но в общем случае приходится раскручивать до нужного места.
Время события
При всей тривиальности ОТО, в пространственно-временном континууме, а так же в администрировании серверов, время совершенно не тривиальная вещь для установления. Во-первых, не все события имеют время. Например, приложение начало писать судорожные буквы в неожиданный лог файл. Буквы важные, но таймстемпа не имеют (и лог в logstash не уходит, потому что никто не думал, что такой лог (в /tmp) быть может). Или, время есть, но очень крупными мазками. Например, по atop'у видно, что приложение завершилось между 12:20 и 12:30. Грубовато.
Иногда бывает так, что для правильной последовательности, нужно синхронное время с разных серверов с точностью меньше секунды. Потому что это важно — сначала запрос, а потом трейс, или же сначала трейс, а потом неответ на не связный с аварией запрос.
А субсекндная точность — это уже совсем сурово. Во-первых ntp может чуть-чуть гулять. Реальный пример из практики: в мрачные времена openvswitch 1.1 у него была дурная привычка добавлять большую (случайную) latency на новые flow (и жрать память до одури, но это отдельный рассказ). И был ntp на всех хостах. И удумал ntp, что джиттеринг большой. И начало время на хостах медленно расходиться, не мало ни много — на 30-90 секунд. Это при том, что все синхронизировались с одного сервера в локалке с пингом в 0.0001с. Итогом стала отдельная проверка для нагиоса, что время на серверах не расходится.
Во-вторых, логгинг может ставить timestamp пост-фактум (для тяжёлых трейсов это может быть много). Ещё веселее, когда одна из жертв возникшей проблемы — ntpd, или даже просто время на сервере. В моей практике как-то было, что программа попутала время (и перестала принимать подписанные сообщения). Forensic показал, что расходится время записи в лог-файл с временем модификации файла, что и стало ключевым для обнаружения бага (возникавшего на стыке летне-зимних часовых поясов).
Бывает так, что разные источники вообще не имеют общего ntp или имеют очень приблизительное представление о времени (саппорт два часа назад сказал, что пять минут назад клиент сказал, что десять минут назад всё упало).
В таких условиях, когда в голове хронологию не удержать, приходится опять же выписывать, на этот раз хронологическую последовательность.
Мотив
Программы никогда не делают ничего просто так. Особенно, в районе всяких плохих ветвлений. Почему программа зависла на выходе? Почему ядро не отдало IO обратно? Почему лог не записался?
Для каждого субъекта действия надо выписать его мотив. Зачем? Почему? Если мотива нет, но есть подозрение на участие, надо хотя бы выписать, что делал и что должен был делать.
В идеальном мире программы не содержат ошибок, в реальном мире — содержат и годами работают с ними. При этом многие ошибки «лежат тихо и ни кого не трогают» в редких уголках кода, пока не случается так, что наступает их очередь. Бывает, починка состоит не в том, чтобы найти и исправить ошибку, а в том, чтобы устранить обстоятельства, вызывающие соответствующий кусок кода. При этом и режим «с ошибкой», и режим «без ошибки» — оба являются более-менее штатными. Наиболее ярким примером такого (не в моей практике) является достижение порога в 512к префиксов в full view в BGP у некоторых старых маршрутизаторов (подробнее).
Субъекты действия
Ещё один важный вопрос: а кто участвует в создании аварийной ситуации? Часто оказывается, что виновником является не только прямой подозреваемый. Из практики: запрос для биллинга не смог отработать. Взгляд показал, что mongodb, хранящая временные самплы, не запущена. Цейтнот потребовал «всё перезапустить», то есть состояние процессов было утеряно. Последующие разбирательства показали, что mongo постоянно завершается (запись в dmesg). При этом никаких OOM'ов. Зато после нескольких минут исследования невнятных логов оказалось, что mongodb достаточно культурно завершается само по нехватке памяти для ответа на сложный запрос.
А логи atop'а показали, что рядом пухнет ceilometer-collector, поджимая и поджимая монгу по памяти. Не было бы atop'а, никто бы ничего не догадался, ибо его перезапустили вместе с mongo. Хотя монга тоже виновата, ибо не написала ясно, что ей не нравится.
Цепочка событий
Часто бывает так, что неожиданность в одном процессе — это ошибка. Но вызвана она другой причиной, часто совсем несвязной.
Бывает так, что нарушается предположение о stateless-поведении системы. Все думают, что повторный запуск на тех же данных даёт те же самые результаты, а в реальности оказывается, что первый запуск и последующие — две большие разницы. При этом авария возникает на первом старте, а после перезапуска всё проходит и работает как положено.
Ещё серьёзнее цепочка отладки становится, если источником проблемы являются данные в БД. Откуда они? Данные могут лежать долго-долго, пока о них споткнётся код. Пример из свежей практики: ceilometer начал падать на метаданных образа с точкой в имени. Образ взял метаданные во время создания снапшота инстанса. А инстанс взял метаданные с хоста, где был запущен (в прошлом году). А метаданные с опечаткой уже давно были поправлены. А проблема укусила через год.
Выстраивание таких цепочек — самая увлекательная часть процесса. В этот момент все связи в системе, под пристальным взглядом подозревающего детектива становятся кристально видны, и часто ужасают своей ненужностью (после того как оно сломалось, становится понятно, как плохо это было). Простой пример из практики: по молодости было принято залихватское решение: сделать на группе однотипных серверов nfs-шару с временными файликами/однострочниками. Это очень удобно, потому что часто файлик с одного сервера нужен на другом, и иметь их в одном месте очень удобно. Так было до тех пор, пока не возникли проблемы на сервере, где была nfs. После ребута… Да, внезапно, оказалось, что path включает в себя этот каталог, и попытка вызывать любую программу приводит к скану nfs-шары.… На этапе логина. В тот раз прорвались через ssh /bin/bash -i. С тех пор я от практики такой шары не отказался, но в path её больше не прописываю.
Процесс разбирательства в причинах часто же позволяет внезапно и очень глубоко понять происходящее в системе с точки зрения архитектуры. Потому что когда всё работает, оно воспринимается как данность. А когда нет… Вот тогда-то и становится понятно, как оно друг с другом связано, как оно работает, а как нет.
В каком-то смысле у меня нет ощущения, что я чувствую, как работает система, пока я не посмотрел, как она ломается. Потому что именно в момент частичной поломки становятся видны все ошибки проектирования, неудачные решения и отсутствие запаса прочности. Ломается всё, вопрос в том, с какими последствиями. Одно решение при фатальной ошибке проинформирует о ней и завершится, а другое обнаружит себя в ветке кода, где обработка ТАКИХ ошибок не предусмотрена, с последствиями соответствующего масштаба.
Следственное заключение
Его написание — обязательная часть forensic. Память у людей плохая, особенно на нелогичные и плохоструктурированные данные. Заключение делится на четыре части: характерные признаки (особенно, цитаты из логов), описание сути произошедшего, метод ранней (или хоть какой-то) диагностики — чаще всего, ещё одна проверка в мониторинг, и рекомендации по устранению. Всё это выписывается в вики (у вас же есть корпоративная вики, правда?), и раскидывается как набор задач для выполнения. Тут есть ещё одна плохая тенденция, с которой надо бороться: «никогда такого не было и снова опять не будет». Если случилось что-то странное, то его не надо игнорировать. Мониторинг, мониторинг, мониторинг. Плюс выписывание всего, что было. Бывает так, что пара-тройка крайне редких (однократных) инцидентов внезапно выстраивается в стройную картинку много позже.… Если фрагменты картинок сохранились. Так что не лениться выписывать, не лениться разбирать, и покрывать тестами.
