Обработка логов с учётом предыдущих сообщений в 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 почём зря.
