Обработка логов с учётом предыдущих сообщений в logstash/elasticsearch

    Про отлов ядерных MCE (machine check error) и прочей гадости с помощью netconsole я писал недавно. Крайне полезная вещь. Одна проблема: throttling на CPU из-за локального перегрева (длительной нагрузки) фиксируется как MCE. Случается бэкап — и админам приходит страшное сообщение об MCE, которое на практике означает «чуть-чуть перегрелось» и точно не требует внимания к себе в 3 часа ночи.

    Смехотворность проблемы ещё тем, что Linux фиксирует MCE после того, как throttling закончился. То есть режим 'normal', но вместо этого оно превращается MCE. Выглядит это так:
    CPU0: Core temperature above threshold, cpu clock throttled (total events = 40997)
    CPU4: Core temperature above threshold, cpu clock throttled (total events = 40997)
    CPU4: Core temperature/speed normal
    CPU0: Core temperature/speed normal
    mce: [Hardware Error]: Machine check events logged
    

    При этом мы точно хотим реагировать на нормальные MCE. Что делать?

    В рамках logstash обработка сообщений предполагается stateless. Видишь сообщение — реагируешь. Внедрять же ради одного типа сообщений более сложную систему — оверкилл.

    Казалось бы, есть фильтр (не путать с output) elasticsearch, который позволяет делать запросы. К сожалению, он не умеет делать 'if'ы, то есть remove_tag и add_tag будут отрабатывать вне зависимости от того, удался поиск или нет.

    Грустно.


    Вторая проблема: как должен выглядеть запрос в elasticsearch? Нам надо интервал времени, относительно текущего, и нам надо фильтровать по текущему хосту (то есть хосту на который пришла MCE).

    Начнём решать в порядке очереди.

    Первое: запрос. query не может содержать нормальный поисковый запрос, а должна содержать query string, который внутри lucene query. Начнём с фиксированного запроса:

    «type:netconsole AND host:compute109 AND message:temperature». (type выставляется в input'е по приёму сообщения от ядра через netconsole).

    Ура, результаты есть, но за большой интервал, который чреват ложными срабатываниями. А как же @ timestamp? Справка по query language довольно скромная, и там не предусматривается никакая математика или спецпеременные. Зато поддерживаются диапазоны с помощью записи вида "[from TO to]".

    Тут у меня случился приступ интуиции и я написал в запросе @ timestamp:[now-2h TO now], хотя про 'now' в документации ни слова. И меня поняли. Провять такие запросы лучше в kibana в поле «query». Быстрая проверка показала, что now-1m в качестве времени тоже прокатывает.

    Итак, запрос стал более приятным: type:netconsole AND host:compute109 AND message:temperature and @timestamp:[now-1m to now]

    Казалось бы, всё будет хорошо. Но — не сработало. Хотя должно было. И тут я посылаю лучи WTF создателям lucene, logstash и elasticsearch. Потому что and и AND — это шесть разных букв.

    Правильно (и только так!) type:netconsole AND host:compute109 AND message:temperature AND @timestamp:[now-1m to now]. Иначе запрос начинает искать сообщения (message) содержащие в себе любые слова temperature, and, @ timestamp).

    Остаётся вопрос: откуда host? Тут уже помогает logstash — он может подставлять переменные в текстовые строки из полей обрабатываемого сообщения.

    Запрос query в конфиге logstash начинает выглядеть так:

    query => "(type:netconsole) AND (host:%{[host]}) AND (@timestamp:[now-1m TO now]) AND (message:temperature)"

    И было бы счастье, если бы не отсутствие if'а внутри фильтра elasticsearch. Получается извращённая конструкция: мы хотим использовать elasticsearch для if'а, но не можем, а там, где мы можем использовать if, мы не можем делать запросы «в прошлое».

    После нескольких десятков попыток «на ёлку влезть» получилась следующая конструкция: Мы, обнаружив MCE, делаем запрос в elastic, и заполняем поле (в сообщении про MCE) «mce_temperature» содержимым message найденного сообщения про 'temperature' на хосте из сообщения про MCE, за последнюю минуту. То есть добавляем к сообщению про MCE предшествующее, про температуру. Если найдём, разумеется.

    Дальше просто: у нас есть MCE и у нас есть содержимое поле mce_temperature с «предыдущим» сообщением. За пределами блока elasticsearch мы пишем:

            if [temperature_mce] =~ /Core temperature.speed normal/ {
                    noop {
                            remove_tag => ["notify"]
                            add_tag => ["supressed"]
                    }
              }
    


    (По тегу notify мы отправляем сообщение в shinken, а supress — просто для человека, увидеть, почему сообщение было не отправлено).

    Отлов тараканов


    Всё было хорошо, кроме того, что в момент, когда я эту статью писал (считая, что проблема решена), мне приходит счастливый такой nagios и говорит голосом человечьим: ** PROBLEM: ALERT… kernel: [8871838.807783] mce: [Hardware Error]: Machine check events logged

    Смотрим:
    [Tue Feb 24 15:51:40 2015] CPU0: Core temperature/speed normal
    [Tue Feb 24 15:52:54 2015] mce: [Hardware Error]: Machine check events logged
    

    Ну спасибо! А у меня интервал [now-1m TO now], то есть 60 секунд. А у событий интервал получился 74 секунды. Так что в финальной версии интервал просмотра пришлось увеличить до 3 минут.

    Вторая «забавная» проблема, которая пришла чуть позже — это проблемы с reverse DNS. Оказалось, DNS не успевает за мониторингом в некоторые моменты и ресолвит не все IP. Мы обычно ресолвим IP в имя и записываем его в поле host (фильтр dns). И получается так, что 'temperature' записалось с IP в поле host (не удалось отресолвить), а MCE пришло с именем хоста. Или наоборот. В любом случае, мерзкое бзз-бззз от телефона ночью без достаточного повода.

    Решение стало тоже простым: мы ресолвим имя, а ip сохраняем в другое поле. И поиск делаем по IP.

    Заключение


    Итоговый конфиг (сниппет):

      if [message] =~ /Machine check events/ {
         elasticsearch {
            hosts => ["localhost"]
            query => "(type:netconsole) AND (source_ip:%{[source_ip]}) AND (@timestamp:[now-3m TO now]) AND (message:temperature)"
            fields => [ "message", "temperature_mce" ]
         }
            if [temperature_mce] =~ /Core temperature.speed normal/ {
                    noop {
                            remove_tag => ["notify"]
                            add_tag => ["supressed"]
                    }
              }
       }
    

    Если вы хотите отключить throttling MCE полностью, то заменить /Core temperature.speed normal/ на /Core temperature/

    Я не уверен, что предложенное решение — это best practice, но оно работает и минимально-интрузивно в конфигурацию. Подобный подход позволяет решать целый класс проблем, связанный с многострочными сообщениями и позволяет принимать ретроспективные ситуативные решения, не разводя bigdata почём зря.
    Webzilla
    Компания

    Похожие публикации

    Реклама
    AdBlock похитил этот баннер, но баннеры не зубы — отрастут

    Подробнее

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

      0
      Про лучи добра в адрес Lucene query parser вы зря. Он case sensitive, как и написано в документации.
        0
        Да. Потому и лучи WTF. Потому что документация, которая противоречит ожиданиям, это типовой WTF. Второй WTF — это за то, как оно не ищет uuid'ы (из-за дефисов). Впрочем, я всё ещё коплю желчи написать про грустную жизнь без грепа и с кибаной. Понимаю, что иначе ни как, но всё равно страшно раздражает и неудобно.
          +1
          Логстеш по умолчанию отправляет все поля в 2 разнцых филда, одно анализируемое
          <fieldname>
          другое не анализируемое
          <fieldname>.raw


          Например можно написать фильтр
          uid.raw:"e47c6b41-e719-4169-a487"
          и оно будет искать по точному совпадению. Если же нужно искать uid в анализируемом тексте, то можно попробовать запрос в кавычки ставить.

          message:"e47c6b41-e719-4169-a487"
          
            0
            Кстати, сработало. Я почему-то был уверен, что кавычки минусы не экранируют, более того, у меня есть стойкое воспоминание, что я это проверял.

            Но сейчас перепроверил, да, кавычки срабатывают. Спасибо.
        +1
        А расскажите, как это все в shinken уходит?
          0
          В output по наличию тега notify дёргается скрипт, который засылает это в shinken. Как со стороны shinken'а принимается — саммоню в топик CyberFlow.
            +1
            У shinken есть модуль ws_arbiter, который позволяет отправлять команды по http. Мы используем его и из скрипта обычным `curl` отправляем результаты в пассивный чек в shinken.

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

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