Вы можете сказать, что “иногда бывает нужно…” Но на самом деле, вы хотите всегда видеть, что у вас в логах, через графический интерфейс. Это позволяет:
- Облегчить жизнь разработчикам и сисадминам, время которых просто жалко и дорого тратить на написание 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 — классный инструмент. Для нас он стал просто незаменимым. Менеджеры следят за всплесками ошибок на фронтэнде после очередного релиза и приходят жаловаться к разработчикам уже “не с пустыми руками”. Те, в свою очередь, находят корреляции с ошибками в приложении, сразу видят их стэки и прочие важнейшие данные, необходимые для дебага. Есть возможность моментально строить различные отчеты из серии “хиты по доменам сайтов” и т.п. Словом, непонятно как мы жили раньше. Но с другой стороны…
“Roburst, Reliable, Predictable” — все это не про ELK. Cистема очень капризная и богатая на неприятные сюрпризы. Очень уж часто приходится копаться во всем этом шатком, извините, Jav-не. Лично я не могу припомнить технологию, которая бы так плохо следовала принципу “настроил и забыл”.
Поэтому за последние 2 месяца мы полностью переделали логи приложения. Как в плане формата (избавляемся от точек в именах, чтобы перейти на ES v.2), так и в плане подхода к тому, что вообще логировать а что нет. Сам по себе этот процесс, имхо, абсолютно нормальный и логичный для такого проекта, как наш — недавно uKit отпраздновал свой первый день рождения.
«В начале пути вы сваливаете в логи как можно больше инфы, т.к. заранее неизвестно, что понадобится, а потом, начав „взрослеть“, постепенно убираете лишнее». (c. pavel_kudinov)
ссылка на оригинал статьи https://habrahabr.ru/post/278729/
Добавить комментарий