Про отлов ядерных MCE (machine check error) и прочей гадости с помощью netconsole я писал недавно. Крайне полезная вещь. Одна проблема: throttling на CPU из-за локального перегрева (длительной нагрузки) фиксируется как MCE. Случается бэкап — и админам приходит страшное сообщение об MCE, которое на практике означает «чуть-чуть перегрелось» и точно не требует внимания к себе в 3 часа ночи.
Смехотворность проблемы ещё тем, что Linux фиксирует MCE после того, как throttling закончился. То есть режим 'normal', но вместо этого оно превращается MCE. Выглядит это так:
При этом мы точно хотим реагировать на нормальные 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]".
Тут у меня случился приступ интуиции и я написал в запросе
Итак, запрос стал более приятным:
Казалось бы, всё будет хорошо. Но — не сработало. Хотя должно было. И тут я посылаю лучи WTF создателям lucene, logstash и elasticsearch. Потому что and и AND — это шесть разных букв.
Правильно (и только так!)
Остаётся вопрос: откуда host? Тут уже помогает logstash — он может подставлять переменные в текстовые строки из полей обрабатываемого сообщения.
Запрос query в конфиге logstash начинает выглядеть так:
И было бы счастье, если бы не отсутствие if'а внутри фильтра elasticsearch. Получается извращённая конструкция: мы хотим использовать elasticsearch для if'а, но не можем, а там, где мы можем использовать if, мы не можем делать запросы «в прошлое».
После нескольких десятков попыток «на ёлку влезть» получилась следующая конструкция: Мы, обнаружив MCE, делаем запрос в elastic, и заполняем поле (в сообщении про MCE) «mce_temperature» содержимым message найденного сообщения про 'temperature' на хосте из сообщения про MCE, за последнюю минуту. То есть добавляем к сообщению про MCE предшествующее, про температуру. Если найдём, разумеется.
Дальше просто: у нас есть MCE и у нас есть содержимое поле mce_temperature с «предыдущим» сообщением. За пределами блока elasticsearch мы пишем:
(По тегу notify мы отправляем сообщение в shinken, а supress — просто для человека, увидеть, почему сообщение было не отправлено).
Всё было хорошо, кроме того, что в момент, когда я эту статью писал (считая, что проблема решена), мне приходит счастливый такой nagios и говорит голосом человечьим: ** PROBLEM: ALERT… kernel: [8871838.807783] 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.
Итоговый конфиг (сниппет):
Если вы хотите отключить throttling MCE полностью, то заменить /Core temperature.speed normal/ на /Core temperature/
Я не уверен, что предложенное решение — это best practice, но оно работает и минимально-интрузивно в конфигурацию. Подобный подход позволяет решать целый класс проблем, связанный с многострочными сообщениями и позволяет принимать ретроспективные ситуативные решения, не разводя bigdata почём зря.
Смехотворность проблемы ещё тем, что 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 почём зря.
