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

в 10:24, , рубрики: elasticsearch, linux kernel, logstash, lucene, Блог компании Webzilla, ит-инфраструктура, Серверное администрирование, системное администрирование

Про отлов ядерных 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 почём зря.

Автор: amarao

Источник

Поделиться

* - обязательные к заполнению поля