Обработка сообщений ядра

    Предисловие


    Страшная сказочка:
    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
    
    Webzilla
    61,00
    Компания
    Поделиться публикацией

    Комментарии 13

      +5
      Имя хоста отличное в примере в конце статьи.
        0
        А как насчет протестировать всю цепочку целиком? Попробуйте

        echo «ioc0: attempting task abort!» > /dev/kmsg

        из-под рута.
          0
          Тут всё сложно — для того, чтобы тестировать «с помощью kmsg», нужно иметь поднятую связку dmesg->netconsole->logstash<-dns<-chief. А это много двигающихся частей, и сложная «тестовая конфигурация», которую поднимать только ради проверки «регэкспы не попортились» смысла нет.

          Да и в чём смысл пересылать сообщение через ядро, когда stdin то же самое даёт, только с меньшими сайд-эффектами? (Да и netconsole есть только на linux, а часть сотрудников маками пользуется — там как быть?).
            0
            Ну я имел в виду скорее полноценное интеграционное тестирование. Проверить регексы — это хорошо. И их надо проверять при каждом изменении. Это юнит-тестирование.
            Но ведь надо иногда проверять и всю цепочку целиком, что быть уверенным что ты действительно получишь алерт при таком вот конкретном сообщении от ядра.
              0
              Это предпродакшен стенд, и под него есть отдельный environment. Но переподнимать его по каждому чиху — очевидный оверкил.
          0
          " nova-compute (написана на python) не отвечает на heartbeat'ы. "

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

          IBM как-бы наш конкурент, но очень правильно сами пишут

          • OpenStack remains an emerging technology
          • It is not mature yet
          • Error handling not robust
          • Understanding the flow of calls and messages is needed
          • Large volume of message based rpc calls
          • Logging is not optimal (either too much or too little)
          • You must be willing to look at code
          • Networking (nova-network) is complicated
          • Multiple bridges
          • IPTables configuration not straight forward
          © IBM Corporation
            +1
            О да, вы нашли фатальный недостаток в чужом продукте. И только вы его можете устранить.

            Nova используется в продакшене не менее чем парой сотен компаний (я за продакшен считаю только public self-serving) уже минимум три года.

            Ту вы приходите и говорите, что вы сделаете лучше.

            okay.jpg
              +1
              Недостаток далеко не один к сожалению, и даже не 100.

              OpenStack сегодня это как Apache Web Server.

              Жутко перегружен, крив до безобразия. Ситуация с сотнями / тысячами разработчиков (и компаний которые очень хотят денег) — рак / лебедь /щука.

              Потом пришел Сысоев и сделал все (nginx) как надо.

              Насчет «сделаете» — сделали уже. Статья была тут на хабре но пришлось ненадолго выключить по ряду политических причин.
                +1
                Скажите, вы его дальше маркетинга смотрели? Из всего опенстека keystone и nova — самые сильные компоненты (свифт не знаю, им другие люди занимаются), neutron тащится в отдалении.

                К nova (при правильном планировании инфраструктуры) у меня лично комплект претензий микроскопический, в основном связанный либо с багами в edge cases (да, разумеется, баги в чужом ПО — это Фатальный Недостаток), либо с желанием как нибудь так исхитриться, чтобы и на ёлку влезть и ресурсов не потратить.

                Насчёт «You must be willing to look at code» — я не верю в существование крупного проекта без этого.

                А ваше исправление Фатального Недостатка подразумевает, что никому на этот код смотреть лучше не надо не придётся?
            0
            Уважаемый автор
            а можно как нибудь увидеть список вот этих волшебных строк ЦЕЛИКОМ?

            [message] =~ /ioc0: attempting task abort!/ or
            [message] =~ /mptbase: ioc0:.+Code=\{Abort\}/ or
            [message] =~ /Device offlined/ or

            ну и с разбором кейсов… что откуда взялось?
              0
              Я попробую собрать. Начиная с определённого момента у нас для каждого сообщения полная строка и линк в багтрекере, но комплекты более ранних просто добавлялись по возникшим ситуациям.
                0
                Знаете это было бы офигенно даже хотя бы просто сам список куда нибудь на gist.github.com скопипастить =)
                а если с разбором кейсов, то вообще очень круто
                  0
                  Ну, тут надо понимать, что делаем мы их под себя — чуть-чуть меняется железо, и комплект сообщений от других драйверов и совсем другой. А реакция на все сообщения с приоритетом ERROR/critical — откровенный перебор. На dell'овых серверах, например, можно получить «ошибку чтения» с CD-привода (виртуального, через IPMI) — и всем на неё пофигу. А у кого-то это может быть бизнес-критикал сообщение.

                  Например, kvm пишет как ошибку действия гостей: kvm [12599]: vcpu0 unhandled wrmsr: 0x682 data 0, хотя ничего такого это не означает. Просто реагировать на все error от ядра не стоит. Более того, местами имеет смысл реагировать на debug/info (флап интерфейса, который не должен флапать), и всё это исключительно business specific.

                  Так что имеет смысл это всё делать под конкретную инсталляцию.

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

            Самое читаемое