Kibana-мать или Зачем вам вообще нужны логи?

Вы можете сказать, что «иногда бывает нужно…» Но на самом деле, вы хотите всегда видеть, что у вас в логах, через графический интерфейс. Это позволяет:

  • Облегчить жизнь разработчикам и сисадминам, время которых просто жалко и дорого тратить на написание grep-конвейеров и парсеров под каждый отдельный случай.
  • Предоставить доступ к информации, содержащейся в логах, умеренно-продвинутым пользователям — менеджерам и техподдержке.
  • И видеть динамику и тенденции появления залогированых событий (например, ошибок).


Так что сегодня вновь поговорим о стэке ELK (Elasticsearch+Logstash+Kibana).
Но на этот раз — в условиях json-логов!

Такой use case обещает наполнить вашу жизнь совершенно новыми красками и заставит испытать полную гамму чувств.

b61bc487a1c24e039bcf7a91b51807ed.jpg


Пролог:

«Пойми, на Хабрахабре только и разговоров, что о Kibana и Elasticsearch. О том, как это чертовски здорово — наблюдать, как огромный текстовый лог превращается в красивые графики, а еле видимая нагрузка на CPU горит где-то в глубине top-а. А ты?… Что ты им скажешь?»

Матчасть


В жизни каждого нормального пацана возникает момент, когда он решил-таки поставить на своем проекте связку ELK.

Схема среднестатистического пайплайна выглядит примерно так:
a5ff097be6e241ad8032f3fc0ade2741.png

Мы шлём в Kibana 2 вида логов:

  1. «Почти обычный» лог nginx. Единственная его изюминка — request-id. Их мы будем генерировать, как сейчас модно, с помощью Lua-в-конфиге™ .
  2. «Необычные» логи самого приложения на node.js. То есть лог ошибок и «продлог», куда летят «нормальные» события — например, «пользователь создал новый сайт».

    Необычность этого типа логов в том, что он:

    • Сериализованный json (логирует события npm-модуль bunyan)
    • Бесформенный. Набор полей у сообщений разный, кроме того, в одних и тех же полях у разных сообщений могут быть разные типы данных (это важно!).
    • Очень жирный. Длина некоторых сообщений превышает 3Мб.


Это, соответственно, front- и back-end-ы всей нашей системы… Приступим!

filebeat

filebeat.yml:
Описываем пути к файлам и добавляем к сообщениям поля, которые нам понадобятся для определения типов логов на этапе фильтрации и при отправке в ES.
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

logstash-listener/01-beats-input.conf:
input {
  beats {
    port => 5044
  }
}



logstash-listener/30-rabbit-output.conf:
output {
        rabbitmq {
            exchange => "logstash-rabbitmq"
            exchange_type => "direct"
            key => "logstash-key"
            host => "localhost"
            port => 5672
            workers => 4
            durable => true
            persistent => true
        }
}



logstash-indexer/01-rabbit-input.conf:
input {
  rabbitmq {
      host => "localhost"
      queue => "logstash-queue"
      durable => true
      key => "logstash-key"
      exchange => "logstash-rabbitmq"
      threads => 4
      prefetch_count => 50
      port => 5672
  }
}



logstash-indexer/09-filter.conf:
В зависимости от формата, прогоняем его через соответствующий кодек.

В случае с 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"
    }
  }
}



logstash-indexer/30-elasticsearch-output.conf:
Имя индекса и document_type для ES берем из полей, которые в самом начале пути приклеили к сообщениям в filebeat-е.
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. Я знал, что рано или поздно мы перейдем и на эту дрянь».


21122a7fbd054d51a740c100f6c31c03.png

Для генерации 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 ошибок:
114d9f654f6641d8ae46f5912789ba64.png

И отдельно взятый тип ошибки на графике и списком эпизодов:
39a2e0c5839b4767ac37352d5d3a9c69.png

Теперь мы знаем, какой баг в системе можно пофиксить когда-нибудь потом, т.к. он слишком редкий. Согласитесь, такой подход куда научнее, чем «за эту неделю было много подобных тикетов в саппорт».

А теперь — срыв покровов: оно работает, но плохо


Кульминация:

«Я понимаю. Ты нашёл в NoSQL рай: у тебя быстро шла разработка, ведь ты хранил все в MongoDB, и тебе не нужны были такие друзья, как я. А теперь, ты приходишь и говоришь: мне нужен поиск. Но ты не просишь с уважением, ты даже не называешь меня Лучшим Поисковым Движком. Нет, ты приходишь ко мне в дом в день рождения Lucene и просишь меня индексировать неструктурированные логи бесплатно»


cb542087eb7d4942b8dd3a98b94010d5.pngНеожиданности
Все ли сообщения из лога попадают в Кибану?
Нет. Не все попадают.

Маппинг запоминает название поля и его тип (число, строка, массив, объект и т.д.). Если мы посылаем в 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 не поддерживаются поля имена которых начинаются с подчеркивания »_».
51db18660c944ed7a28b39c1675dad8e.png

Комментарий разработчика

Автоматическое уползание данных в соседние инстансы 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)

© Habrahabr.ru