Предисловие

Страшная сказочка:

EDAC MC0: 1 CE read ECC error on CPU#0Channel#1_DIMM#0 (channel:1 slot:0)
EXT4-fs error: ext4_wait_block_bitmap:445: Cannot read block bitmap
Out of memory: Kill process 95 (sshd) score 31 or sacrifice child
CMCI storm detected: switching to poll mode
page allocation failure: order:1, mode:0x4020
invalid opcode: 0000 [#1] SMP

Неприятно выглядит, правда? Список может быть очень длинным очень длинный. В этой статье я расскажу как с этим жить и что мы с ним сделали.

Часть из этих сообщений в примерах выше заставит вас погрузиться в бездны современной архитектуры процессоров («CMCI storm», удачи в поиске дороги назад, из дебрей интернетов)… Cтранные вещи в ядре могут нарушать ожидания о том, как работают компьютеры, делая последующую отладку очень затруднённой. Отсутствие знания о том, что случилось может даже оставить с грустным ответом «какая-то неведомая фигня, ребутнули, вроде, прошло».

Странные вещи можно разделить на четыре группы:

• Отказ центрального оборудования (в том числе процессора. Как вам сообщение «Generic CACHE Level-2 Generic Error»?)
• Отказ периферийного оборудования (CMCI storm от сетевой карты? Отвалившийся SAS HBA?)
• Ошибки в ядре
• Нехватка ресурсов

Иногда ошибки происходят в sad path (триада понятий: happy path, sad path, bad path) — грустно, но предсказуемо. Есть осмысленная ветка кода, которая на эту проблему реагирует. Ядро поделило на ноль, жёсткий диск начал сыпать Buffer I/O error on device… и т.д. Чаще всего подобные ошибки либо означают перезагрузку сервера (в идеале — автоматическую), либо обрабатываются в районе ПО (одинокий сломавшийся жёсткий диск — даже не проблема, а так, рейд пересобрать после замены), либо в железе (recoverable ECC error у памяти). Иногда ошибки даже проходят незамеченными (например, IO error для CD-привода, одинокий segmentation fault для программы, которая «перезапустилась и продолжает работать»).

Печальный пример

Но иногда ошибки не обрабатываются «ожидаемым» образом, а приводят систему в состояние, когда «никогда такого не было, и вот опять» (bad path).

Живой пример из недавней практики: RAID-контроллер на сервере ушёл в оффлайн и тут же вернулся обратно (PCI bus reset силами watchdog'а в драйвере). Все массивы были обнаружены как «новые» диски и получили новые же буквы, uuid'ы остались те же. Всё, что было в databag'ах chef'а было подмонтировано при первой же возможности по тем же самым путям.

Получилась конструкция, мягко говоря, не предусмотренная КоАП:
/dev/sda -> /mountpoint (битый)
/dev/sdd ->/mountpoint (рабочий)
При этом файлы, которые были открыты на 'битой' версии /mountpoint давали IO error на любые операции, а новые файлы создавались на рабочей /mountpoint. Оттуда же брались и новооткрытые на чтение файлы. При этом своп был на «битой» /dev/sda и можно было наблюдать фантастические сообщения:

Read-error on swap-device (8:0:330471000)
Write-error on swap-device (8:0:362589920).

(до этого момента я не знал, что Linux может сделать read error на swap и остаться жить).

Сам sda был хардварным рейдом, но кому поможет избыточность дисков, если отваливается контроллер целиком? Получившаяся конструкция полностью проходила все проверки. Диск есть? Есть и примонтирован. Состояние рейда? ОК! Свободное место? Есть. Размер очереди на IO? Всё ок. Счётчик ошибок для подмонтированного блочного устройства? По нулям (устройство-то новое). Новые запросы на запись отрабатывают? Отрабатывают. Чего ещё желать?

А ведь при этом куча ПО словила ошибку записи и перешла в неожиданное состояние. Кто-то завершился, кто-то продолжал писать в файл не смотря на ошибки (то же ядро со swap-файлом). Даже специальная проверка на то, все диски, которые ожидает увидеть chef, примонтированы, тоже говорила «ок».

После разбора полётов мы изменили проверку на «примонтированность» с проверки на «диск примонтирован» на «диск примонтирован не более одного раза». Ну и анализ логов. Собственно, о них и статья.

Отказы центрального оборудования

Тяжело собирать выбитые зубы сломанными руками. То же самое касается реакции системы на отказ центральных компонент. Если у сервера проблемы с питанием процессора, с самим процессором (да, они тоже ломаются), оперативной памятью, контроллером PCI или другими критическими для работы компонентами, то он либо виснет (и тут приходит watchdog и перезагружает), либо паникует. Однако, есть целый класс некритических ошибок (например, ошибка работы с памятью, хотя и очень плохая, но часто не приводит к перезагрузке). Иногда ошибается процессор, сбоит программа в виртуальной машине ACPI, чудачат контроллеры памяти или PCI-шины. Иногда эти ошибки «всего лишь» меняют несколько байт (бит?) в некоторых местах. Последствия этого предсказать невозможно. То есть не «трудно», а «невозможно».

Ошибки в ядре

Тоже бывают. BUG on bla-bla-bla. Неприятное, но не смертельное «ну не получилось». В некоторых случаях ошибка фатальна и ведёт к panic, в некоторых, с точки зрения ядра, нет. Однако, последствия ошибки ядра опять же, очень трудно описать с позиции userspace. Раньше всё было хорошо, ничего не поменялось, и вот уже всё плохо.

История

В ядре что-то пошло не так. То ли мьютекс, то ли попортилась память, но на выходе мы получили странный трейс, и неубиваемый процесс, жрущий 100% CPU. Обнаружил я его, когда увидел, что nova-compute (написана на python) не отвечает на heartbeat'ы. Пошёл на хост. Вижу, в top'е, 100% CPU. Не перезапускается. Не убивается (kill -9). Strace показывает ничего (нет запроса).

Погодь, опытный админ. Этот процесс не был в 'D', он не «ушёл в IO и не вернулся». Он вообще не выполнял никакого syscall'а. Он просто ел 100% CPU (в ядерном контексте?). Он был 'R' и он игнорировал сигнал 9 (и он был не init). В том случае историю до конца не раскопали, но предположение было, что либо в результате ошибки, либо незамеченного повреждения памяти, при переключении контекста ядро не могло обработать какую-то блокировку, так что CPU time засчитывалось процессу, но процессор при этом работал в контексте ядра. То есть «висит груша, жрёт 100%, прибить нельзя». Удивительным образом, процесс самозавершился (или дообработал kill -9) через минут 10, после чего shutdown/migration прошёл штатным образом (типа, happy end).

Нехватка ресурсов

Когда вашему уютненькому приложению говорят «фиг тебе, а не файловый сокет», это sad path. Всё под контролем и хорошо. Но когда сетевой драйвер не может получить себе цельный кусок памяти на 8кБ (для jumbo frame) — «page allocation failure: order:2», и молча дропает пакет — это плохо. То есть снаружи видно, что плохо, а внутри всё хорошо, кроме строчек в dmesg. Основная причина этой ошибки — фрагментация памяти (куски памяти должны быть непрерывными), плюс особенность используемого (на тот момент) ядра. Кстати, в качестве временной меры (до вывода сервера из эксплуатации) мы чуть-чуть понизили размер jumbo frame до состояния, когда модулю было достаточно 2 страниц подряд, а не 4. Чуть-чуть полегчало.

А бывает так, что приходит волшебный OOM killer и отбирает новогодние подарки у какого-нибудь процесса. Особенно печально это выглядит, когда умирает вспомогательный процесс (например, epam для beam.smp в контексте erlang'а) и про это никто не в курсе. Ещё интереснее, когда нехватка памяти случается на очень занятой системе — мало того, что OOM killer убивает кого попало, процесс поиска «жертвы» может затянуться на десятки секунд, и в течение этого времени сервер не делает ничего. Вообще ничего — ни сеть, ни диск не работают. Только ядро шуршрит по структурам в памяти. А потом (за вычетом «не проснувшегося лузера») продолжает работать так, как будто ничего не произошло. И гадай после этого, почему сработал failover с таймаутом в 20с.

Подводя к теме рассказа

Во всём этом грустном есть одно общее — ядро пишет о причинах грусти в dmesg. Даже если ядро решает запаниковать, оно сначала в dmesg пишет, а потом паникует. Разбор причин post mortem — едва ли не самая важная работа системного администратора, она напоминает работу специалиста по вещественным уликам. Мельчайшие следы того, что остались, позволяют складывать вместе кусочки мозаики. Особо мозаика интересна, когда эксцесс происходит в масштабе нескольких серверов.

Вторая важная вещь: о всех этих гадостях лучше узнавать когда они происходят. Потому что между «печальным трейсом» в dmesg и деградацией сервиса, которая будет заметна со стороны, могут проходить значительные интервалы времени (до нескольких десятков часов). И есть время «поправить так, как будто ничего и не было».

Таким образом, хочется и «собирать логи», и «реагировать на них».

Те, кто про себя уже вздохнул «ну, ещё один рассказ про netconsole» — нет. Про netconsole я скажу несколько слов, а потом расскажу как с этим жить потом, когда данные уже получены по UDP.

netconsole

Подробное howto уже писалось: habrahabr.ru/post/131220, а тут я дам краткую выжимку: netconsole — модуль ядра для отправки журнала ядра в UDP-пакетах. Заметим, это настолько низкий уровень, что на нём не работает даже ARP, то есть вы должны указать мак-адрес получателя.

Зато netconsole работает, даже если выполомаете весь сетевой стек. Например, сделаете rmmod ip, или, или удалите IP-адрес с интерфейса, или при включенном бриджинге, rmmod openvswitch. Очень смешно видеть, как ядро по сети пишет о том, что вся сеть сломана.

При загрузке модуля ему указывается локальный интерфейс, IP-адрес с которого отправлять, IP и MAC-адреса получателя. Если трафик отправляется за пределы сегмента сети, то в качестве MAC'а указывается MAC-адрес шлюза (.1).

Приём

Всё интересное начинается тут. Собирать netconsole можно с помощью syslog (и его вариаций — syslog-ng, rsyslog). В нашем случае используется logstash. Про эту конструкцию мы уже писали: писали.

Логи во-первых принимаются, во-вторых маркируются по input'у как 'netconsole' (условно выбранная нами метка), а главное, производится запись имени сервера вместо адреса. Это очень важный процесс и про него чуть ниже.

Пример конфига:

input {
  udp {
      type => "netconsole"
      port => "6666"
      buffer_size => "1048576"
  }
}

filter {
  if [type] == "netconsole" {
    dns {
      action => "replace"
      reverse => ["host"]
    }

    mutate {
      add_field => ["syslog_host", "%{host}"]
    }
  }
}

Единственное нетривиальное тут — это выставление поля host. И оно очень важно, потому что иначе потом dmesg не найти будет. Настолько важно, что у нас сейчас идёт дискуссия о том, надо ли нам на хостах мониторинга выписывать все адреса в /etc/hosts и использовать его, для того, чтобы авария на dns в момент записи трейса, не попортила бы лог с ошибками.

Далее, нам надо эти логи смотреть. В контексте kibana, для собственно удобства, было добавлена колоночка 'TERMS' с выбором: syslog или netconsole. Получившийся фильтр выглядит так:
host must 'hostname' and source must 'netconsole'.

Получившееся уже можно читать, но очень неудобно. Для удобства я использую ещё ручной скрипт,
который выдирает dmesg просто плейнтекстом из elasticsearch'а:

#!/usr/bin/python
from pyelasticsearch import *
import json
import sys

es = ElasticSearch('http://elastic.local:9200/')
q=json.load(sys.stdin)
res=es.search(q)['hits']['hits']
for i in res:
        print(i['_source']['message']),

На stdin ему кормится заинтересовавший запрос из kibana в виде JSON (кнопка 'i' в интересующем виджете), на stdout оно выдаёт аккуратную стопочку строк без лишнего мусора. Впрочем, про жизнь и борьбу с Kibana я напишу отдельно.

Мониторинг

Выше был показано как смотреть данные post mortem. Есть ещё задача реагировать на «плохие» строки и оповещать о них shinken (nagios). А уж как действовать на нервы админам, nagios и сам отлично знает.

Делается это с помощью фильтров.

filter {
 if [type] == "netconsole" {
    if (
            [message] =~ /ioc0: attempting task abort!/ or
            [message] =~ /mptbase: ioc0:.+Code=\{Abort\}/ or
            [message] =~ /Device offlined/ or
            ...
            [message] =~ /Read-error on swap-device/ or
            "1" == "2"          
  ) {
      noop {
        add_tag => ["notify"]
      }
}

Мы выставляем флаг notify, если нам не нравится строчка. Обратите внимание на «1» == «2» — эта строчка добавлена для того, чтобы смело писать or на каждой «осмысленной» строке и не бояться поломать синтаксис.

Обработка флага происходит очень просто:

output {
  if "notify" in [tags] {
    exec {
      command => "/usr/lib/nagios/plugins/log_event_sender.sh %{syslog_host} log_event '%{message}'"
    }
  }
}

Тестирование

Я бы сказал, что на этом «всё», если бы не одно «но». Некоторые виды страшных строк появляются крайне редко — и очень сложно узнать, сработает ли мониторинг на них или нет. До какого-то момента мы полагались на «мы его не сломаем», но опасения нелепой опечатки в фильтрах, полностью отключающей срабатывания на ошибки, было слишком большим.

И родился микрофреймворк для тестирования.

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

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

Дальше идёт простейший тест: мы запускаем logstash в stdin/stdout режиме, и проверяем, что число входных строк равно числу выходных (с меткой notify). Если оно расходится — значит, кто-то что-то сломал. Если сходится, значит, на каждую плохую строчку что-то её да поймает.

Ниже run_test.sh, в котором ничего интересного не происходит — пишем микроконфиг с помощью echo, вставляем в середину его фильтр, который тестируем, проверяем, что всё совпало. Если нет — админ сам разбирается что не так.

#!/bin/bash
TMPC=logstash-test-$RANDOM.conf
TMPO=logstash-test-output-$RANDOM.txt
LOGSTASH=logstash/logstash-1.4.2/bin/logstash
TIMEOUT=60
FILTERS=....../filters.conf.erb

if test ! -d logstash;
then
    echo "No local logstash found at $LOGSTASH (Please download/unpack)"
    exit -1
fi
echo 'input { stdin { type => "netconsole" } }' > $TMPC
cat $FILTERS >>$TMPC
echo 'output { if "notify" in [tags] { stdout { } } }' >>$TMPC
#echo $LOGSTASH --quiet -f $TMPC
cat netconsole_examples.txt | timeout -s SIGKILL $TIMEOUT $LOGSTASH --quiet -f $TMPC  > $TMPO
if test `wc -l netconsole_examples.txt | awk '{print $1}'` -ne `wc -l $TMPO | awk '{print $1}'`; then
    echo Netconsole test FAILED
    echo Input: `wc -l netconsole_examples.txt`
    echo Output: `wc -l $TMPO`
    echo not removing files $TMPC and $TMPO
    exit 1
else
    echo netsonsole test PASSED
    rm $TMPC $TMPO
    exit 0
fi

После каждого редактирования надо/можно запустить run_test.sh и проверить, что оно работает. netconsole_examples.txt, заодно, служит отличным методом для хранения всех самых самых ужасных вещей, какие только можно встретить в этой жизни. (Сами эти строчки комментируются по вкусу, с добавлением ссылок на статьи в Вики, где хранятся post mortem разборы и т.д.).

На выходе мониторинга имеем вот такие сообщения:

** PROBLEM alert - database1984.utah42.nsa.gov/log_event is CRITICAL **
Shinken Notification

Notification Type: PROBLEM

Service: log_event
Host: database1984.utah42.nsa.gov
Address: 238.211.14.5
State: CRITICAL

Date/Time: 23-01-2015 Additional Info : Jan 23 03:59:21 database1984 kernel: [15941700.780017] mce: [Hardware Error]: Machine check events logged