Kibana-мать или Зачем вам вообще нужны логи?
Вы можете сказать, что «иногда бывает нужно…» Но на самом деле, вы хотите всегда видеть, что у вас в логах, через графический интерфейс. Это позволяет:
- Облегчить жизнь разработчикам и сисадминам, время которых просто жалко и дорого тратить на написание grep-конвейеров и парсеров под каждый отдельный случай.
- Предоставить доступ к информации, содержащейся в логах, умеренно-продвинутым пользователям — менеджерам и техподдержке.
- И видеть динамику и тенденции появления залогированых событий (например, ошибок).
Так что сегодня вновь поговорим о стэке ELK (Elasticsearch+Logstash+Kibana).
Но на этот раз — в условиях json-логов!
Такой use case обещает наполнить вашу жизнь совершенно новыми красками и заставит испытать полную гамму чувств.
Пролог:
«Пойми, на Хабрахабре только и разговоров, что о Kibana и Elasticsearch. О том, как это чертовски здорово — наблюдать, как огромный текстовый лог превращается в красивые графики, а еле видимая нагрузка на CPU горит где-то в глубине top-а. А ты?… Что ты им скажешь?»
Матчасть
В жизни каждого нормального пацана возникает момент, когда он решил-таки поставить на своем проекте связку ELK.
Схема среднестатистического пайплайна выглядит примерно так: 
Мы шлём в Kibana 2 вида логов:
- «Почти обычный» лог nginx. Единственная его изюминка — request-id. Их мы будем генерировать, как сейчас модно, с помощью Lua-в-конфиге™ .
- «Необычные» логи самого приложения на node.js. То есть лог ошибок и «продлог», куда летят «нормальные» события — например, «пользователь создал новый сайт».
Необычность этого типа логов в том, что он:
- Сериализованный json (логирует события npm-модуль bunyan)
- Бесформенный. Набор полей у сообщений разный, кроме того, в одних и тех же полях у разных сообщений могут быть разные типы данных (это важно!).
- Очень жирный. Длина некоторых сообщений превышает 3Мб.
Это, соответственно, front- и back-end-ы всей нашей системы… Приступим!
filebeat
filebeat:
prospectors:
-
paths:
- /home/appuser/app/production.log.json
input_type: log
document_type: production
fields:
format: json
es_index_name: production
es_document_type: production.log
-
paths:
- /home/appuser/app/error.log.json
input_type: log
document_type: production
fields:
format: json
es_index_name: production
es_document_type: production.log
-
paths:
- /home/appuser/app/log/nginx.log
input_type: log
document_type: nginx
fields:
format: nginx
es_index_name: nginx
es_document_type: nginx.log
registry_file: /var/lib/filebeat/registry
output:
logstash:
hosts: ["kibana-server:5044"]
shipper:
name: ukit
tags: ["prod"]
logging:
files:
rotateeverybytes: 10485760 # = 10MB
logstash
input {
beats {
port => 5044
}
}
output {
rabbitmq {
exchange => "logstash-rabbitmq"
exchange_type => "direct"
key => "logstash-key"
host => "localhost"
port => 5672
workers => 4
durable => true
persistent => true
}
}
input {
rabbitmq {
host => "localhost"
queue => "logstash-queue"
durable => true
key => "logstash-key"
exchange => "logstash-rabbitmq"
threads => 4
prefetch_count => 50
port => 5672
}
}
В случае с nginx, это будут вот такие «необычные» регулярки-полуфабрикаты, предлагаемые фильтрующим модулем «grok» (слева), и названия полей, в которые попадут заматченые данные (справа). Для пущей красоты у нас есть еще фильтр geoip, который определяет локацию клиента. В Кибане можно будет сделать «географию» клиентов. Базу качаем отсюда dev.maxmind.com/geoip/legacy/geolite.
А в случае с json, как видите, ничего делать вообще не надо, что не может не радовать.
filter {
if [fields][format] == "nginx" {
grok {
match => [
"message", "%{IPORHOST:clientip} - \[%{HTTPDATE:timestamp}\] %{IPORHOST:domain} \"(?:%{WORD:verb} %{NOTSPACE:request}(?: HTTP/%{NUMBER:httpversion})?|%{DATA:rawrequest})\" %{NUMBER:status:int} (?:%{NUMBER:bytes:int}|-) %{QS:referrer} %{QS:agent} %{NUMBER:request_time:float} (?:%{NUMBER:upstream_time:float}|-)( %{UUID:request_id})?"
]
}
date {
locale => "en"
match => [ "timestamp" , "dd/MMM/YYYY:HH:mm:ss Z" ]
}
geoip {
source => "clientip"
database => "/opt/logstash/geoip/GeoLiteCity.dat"
}
}
if [fields][format] == "json" {
json {
source => "message"
}
}
}
output {
elasticsearch {
hosts => ["localhost:9200"]
index => "logstash-%{[fields][es_index_name]}-%{+YYYY.MM.dd}"
document_type => "%{[fields][es_document_type]}"
}
}
Связывание событий в логах фронта и бэка
Завязка:
«У нас было 2 типа логов, 5 сервисов в стэке, полтерабайта данных в ES, а также несчетное множество полей в логах приложений. Не то чтобы это был необходимый набор для риалтайм-анализа состояния сервиса, но когда начинаешь задумываться еще и о связывании событий nginx-а и приложения, становится сложно остановиться.
Единственное, что вызывало у меня опасения — Lua. Нет ничего более беспомощного, безответственного и порочного, чем Lua в конфигах Nginx. Я знал, что рано или поздно мы перейдем и на эту дрянь».
Для генерации request-id на Nginx-е будем использовать Lua-библиотеку, которая генерирует uuid-ы. Она, в целом, справляется со своей задачей, но пришлось немного доработать ее напильником — ибо в первозданном виде она (та-дам!) дуплит uuid-ы.
http {
...
# Либа для генерации идентификаторов запросов
lua_package_path '/etc/nginx/lua/uuid4.lua';
init_worker_by_lua '
uuid4 = require "uuid4"
math = require "math"
';
...
# Объявляем переменную request_id,
# обычный способ (set $var) не будет работать в контексте http
map $host $request_uuid { default ''; }
# Описываем формат лога
log_format ukit '$remote_addr - [$time_local] $host "$request" '
'$status $body_bytes_sent "$http_referer" '
'"$http_user_agent" $request_time '
'$upstream_response_time $request_uuid';
# Путь к файлу и формат лога
access_log /home/appuser/app/log/nginx.log ukit;
}
server {
...
# Генерируем id запроса
set_by_lua $request_uuid '
if ngx.var.http_x_request_id == nil then
return uuid4.getUUID()
else
return ngx.var.http_x_request_id
end
';
# Отправляем его в бекэнд в виде заголовка, чтобы он у себя тоже его залогировал.
location @backend {
proxy_pass http://127.0.0.1:$app_port;
proxy_redirect http://127.0.0.1:$app_port http://$host;
proxy_http_version 1.1;
proxy_set_header Connection "";
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Nginx-Request-ID $request_uuid; #id запроса
proxy_set_header Host $host;
...
}
...
}
На выходе получаем возможность по событию в логе приложения найти повлекший его запрос, прилетевший на Nginx. И наоборот.
Довольно быстро обнаружилось, что наши «вселенски-уникальные» айдишники не такие уж уникальные. Дело в том, что randomseed библиотека берет из таймстампа на момент запуска nginx-воркера. А воркеров у нас столько, сколько ядер у процессора, и запускаются они одновременно… Не беда! Подмешаем туда pid воркера и будет нам счастье:
...
local M = {}
local pid = ngx.worker.pid()
-----
math.randomseed( pid + os.time() )
math.random()
...
P.S. В репозитарии Debian-а есть готовый пакет nginx-extras. Там сразу есть Lua и еще куча полезных модулей. Рекомендую, вместо того чтобы вкомпиливать модуль Lua руками (еще бывает openresty, но я не пробовал).
Группировка ошибок по частоте возникновения.
Kibana позволяет группировать (строить рейтинги) событий на основе одинаковых значений полей.
В логе ошибок у нас есть стэктрейсы, они почти идеально подходят в качестве ключа группировки, но загвоздка в том, что в Кибане нельзя группировать по ключам длиннее 256 символов, а стэки конечно длиннее. Поэтому мы делаем md5-хэши стэктрейсов в bunyan и группируем уже по ним. Красота!
Так выглядит топ 20 ошибок: 
И отдельно взятый тип ошибки на графике и списком эпизодов: 
Теперь мы знаем, какой баг в системе можно пофиксить когда-нибудь потом, т.к. он слишком редкий. Согласитесь, такой подход куда научнее, чем «за эту неделю было много подобных тикетов в саппорт».
А теперь — срыв покровов: оно работает, но плохо
Кульминация:
«Я понимаю. Ты нашёл в NoSQL рай: у тебя быстро шла разработка, ведь ты хранил все в MongoDB, и тебе не нужны были такие друзья, как я. А теперь, ты приходишь и говоришь: мне нужен поиск. Но ты не просишь с уважением, ты даже не называешь меня Лучшим Поисковым Движком. Нет, ты приходишь ко мне в дом в день рождения Lucene и просишь меня индексировать неструктурированные логи бесплатно»
Неожиданности
Все ли сообщения из лога попадают в Кибану?
Нет. Не все попадают.
Маппинг запоминает название поля и его тип (число, строка, массив, объект и т.д.). Если мы посылаем в ES сообщение, в котором есть поле, уже существующее в маппинге, но тип не совпадает с тем, что было в этом поле раньше (например, в маппинге — массив, а пришел объект), то такое сообщение не попадет в ES, а в его логе будет не слишком очевидное сообщение:
{«error»: «MapperParsingException[object mapping for [something] tried to parse as object, but got EOF, has a concrete value been provided to it?]»
Источник
Имена полей в json-логах
Elasticsearch v2.x не принимает сообщения, в которых есть поля, имена которых содержат точки. В v1.x этого ограничения не было, и мы не можем перейти на новую версию, не переделав все логи, т.к. у нас такие поля уже «исторически сложились».
Источник
Кроме того, в Kibana не поддерживаются поля имена которых начинаются с подчеркивания »_».
Комментарий разработчика
Автоматическое уползание данных в соседние инстансы ES
По-умолчанию в ES включена опция Zen Discovery. Благодаря ей, если вы запустите несколько инстансов ES в одной сети (например, несколько докер-контейнеров на одном хосте), то они друг друга найдут и поделят данные между собой. Очень удобный способ смешать продуктивные и тестовые данные и долго с этим разбираться.Оно падает и потом долго поднимается. Это еще больнее, когда docker
Стэк вовлеченных в нашу преступную схему демонов достаточно многочисленен. Кроме того, некоторые из них любят непонятно падать и очень долго подниматься (да, те, что на Java). Чаще всех зависает logstash-indexer, в логах при этом тишина или неудачные попытки послать данные в ES (видно, что они были давно, а не вот только что). Процесс жив, если послать ему kill — он очень долго умирает. Приходится слать kill -9, если некогда ждать.
Реже, но тоже бывает, что падает Elasticsearch. Делает он это «по-английски» (т.е. молча).
Чтобы понять, кто из них двоих упал, делаем http-запрос в ES — если ответил, значит лежит не он. Кроме того, когда у вас относительно много данных (скажем, 500G), то ваш Elasticsearch после запуска будет еще около получаса просасывать эти данные, и в это время они будут недоступны. Данные самой Kibana хранятся там же, поэтому она тоже не работает, пока ее индекс не подхватится. По закону подлости, до нее обычно очередь доходит в самом конце.
Приходится мониторить мониторингом длину очереди в rabbitmq, чтобы оперативно реагировать на инциденты. Раз в неделю они стабильно случаются.
А когда у вас всё в docker-е, и контейнеры слинкованы между собой, то вам нужно перезапустить еще и все контейнеры которые были слинкованы с контейнером ES, кроме него самого.
Большие дампы памяти при OOM
По-умолчанию в ES включена опция HeapDumpOnOutOfMemoryError. Это может привести к тому, что у вас неожиданно закончилось место на диске из-за одного или нескольких дампов размером ~30GB. Сбрасываются они, разумеется, в директорию, где лежат бинарники (а не туда, где данные). Происходит это быстро, мониторинг даже не успевает прислать смс-ку. Отключить это поведение можно в bin/elasticsearch.in.sh.
Производительность
В Elasticsearch существует т.н. «маппинг» индексов. По-сути, это схема таблицы, в которой хранятся данные в формате «поле — тип». Создается она автоматически на основе поступающих данных. Это значит, что ES запомнит имя и тип данных поля, исходя из того, данные какого типа пришли в этом поле в первый раз.
Например, у нас есть 2 очень разных лога: access-log nginx и production-log nodejs-приложения. В одном стандартный набор полей, он короткий, типы данных никогда не меняются. В другом же, напротив, полей много, они nested, они свои у каждой строчки лога, названия могут пересекаться, данные внутри полей могут быть разных типов, длина строки доходит до 3 и более Mб. В итоге автомаппинг ES делает так:
Маппинг здорового «прямоугольного» лога nginx:
root@localhost:/ > du -h ./nginx.mapping
16K ./nginx.mapping
Маппинг курильщика «бесформенного» json-лога нашего приложения:
root@localhost:/ > du -h ./prodlog.mapping
2,1M ./prodlog.mapping
В общем, оно сильно тормозит как при индексации данных, так и при поиске через Kibana. При этом, чем больше накопилось данных, тем хуже.
Мы пытались бороться с этим закрытием старых индексов c помощью curator. Положительный эффект безусловно есть, но все-таки это анестезия, а не лечение.
Поэтому мы придумали более радикальное решение. Весь тяжелый nested-json в production-логе отныне будет логироваться в виде строки в специально-отведенном одном поле сообщения. Т.е. вот прямо JSON.stringify (). За счет этого набор полей в сообщениях становится фиксированным и коротким, мы приходим к «легкому» маппингу как у nginx-лога.
Конечно, это своего рода «ампутация с дальнейшим протезированием», но вариант рабочий. Будет интересно увидеть в комментариях, как еще можно было сделать.
Промежуточный итог
Стэк ELK — классный инструмент. Для нас он стал просто незаменимым. Менеджеры следят за всплесками ошибок на фронтэнде после очередного релиза и приходят жаловаться к разработчикам уже «не с пустыми руками». Те, в свою очередь, находят корреляции с ошибками в приложении, сразу видят их стэки и прочие важнейшие данные, необходимые для дебага. Есть возможность моментально строить различные отчеты из серии «хиты по доменам сайтов» и т.п. Словом, непонятно как мы жили раньше. Но с другой стороны…
«Robust, Reliable, Predictable» — все это не про ELK. Cистема очень капризная и богатая на неприятные сюрпризы. Очень уж часто приходится копаться во всем этом шатком, извините, Jav-не. Лично я не могу припомнить технологию, которая бы так плохо следовала принципу «настроил и забыл».
Поэтому за последние 2 месяца мы полностью переделали логи приложения. Как в плане формата (избавляемся от точек в именах, чтобы перейти на ES v. 2), так и в плане подхода к тому, что вообще логировать, а что нет. Сам по себе этот процесс, имхо, абсолютно нормальный и логичный для такого проекта, как наш — недавно uKit отпраздновал свой первый день рождения.
«В начале пути вы сваливаете в логи как можно больше инфы, т.к. заранее неизвестно, что понадобится, а потом, начав «взрослеть», постепенно убираете лишнее». (c. pavel_kudinov)
