Thank you for reading this post, don't forget to subscribe!
Клиентская часть (Агент)
Рассмотрим пример доставки лога от Docker контейнера.
Есть два варианта (на самом деле их больше тыц) как писать лог Docker контейнеров. В своем дефолтном состоянии, используется Logging Driver — “JSON file”, т.е. пишет классическим методом в файл. Второй способ — это переопределить Logging Driver и слать лог сразу в Fluentd.
Решили мы попробовать второй вариант.
Далее столкнулись с такой проблемой, что если просто сменить Logging Driver и, если вдруг, TCP сокет Fluentd, куда должны сыпаться логи, не доступен, то контейнер вообще не запустится. А если TCP сокет Fluentd пропадет, когда контейнер ранится, то логи начинают копиться в буфер.
Происходит это потому, что у Docker есть два режима доставки сообщений от контейнера к Logging Driver:
direct — является дефолтным. Приложение падает, когда не может записать лог в stdout и/или stderr.
non-blocking — позволяет записывать логи приложения в буфер при недоступности сокета коллектора. При этом, если буфер полон, новые логи начинают вытеснять старые.
Все эти вещи подтянули дополнительными опциями Logging Driver
(--log-opt).
Но, так как нас не устроил ни первый, ни второй вариант, то мы решили не переопределять Logging Driver и оставить его дефолтным.
Вот тут и настал момент, когда мы задумались о том, что необходимо устанавливать агента, который бы старым, добрым способом вычитывал с помощью tail лог файл. Кстати, я думаю не все задумывались над тем, что происходит с tail, когда ротейтится лог-файл, а оказалось все достаточно просто, так как tail снабжен ключем -F (same as --follow=”name” --retry), который способен следить за файлом и переоткрывать его в случае необходимости.
Итак, первое на что было обращено внимание — это продукт FluentBit.
Настройка FluentBit достаточна проста, но мы столкнулись с несколькими неприятными моментами.
Проблема заключалась в том, что если TCP сокет коллектора не доступен, то FluentBit начинает активно писать в буфер, который находится в памяти и по мере его заполнения, начинает вытеснять (перезаписывать) лог, до тех пор, пока не восстановит соединение с коллектором, а следовательно, мы теряем логи. Это не критикал, но крайне неприятно.
Решили эту проблему следующим образом.
FluentBit в tail плагине имеет следующие параметры:
DB — определяет файл базы данных, в котором будет вестись учет файлов, которые мониторятся, а также позицию в этих файлах (offsets).
DB.Sync — устанавливает дефолтный метод синхронизации (I/O). Данная опция отвечает за то, как внутренний движок SQLite будет синхронизироваться на диск.
И стало все отлично, логи мы не теряли, но столкнулись со следующей проблемой — эта штука очень жутко начала потреблять IOPs. Обратили на это внимание когда заметили, что инстансы начали тупить и упираться в IO, которого раньше хватало за глаза и сейчас объясню почему.
Мы используем EC2 инстансы (AWS) и тип EBS — gp2 (General Purpose SSD). У них есть такая штука, которая называется “Burst performance”. Это когда EBS способен выдерживать некоторые пики возрастающей нагрузки на файловую систему, например запуск какой-нибудь крон задачи, которая требует интенсивного IO и если ему недостаточно “baseline performance”, инстанс начинает потреблять накопленные кредиты на IO т.е. “Burst performance”.
Так вот, наша проблема заключалась в том, что были вычерпаны кредиты IO и EBS начал захлебываться от его недостатка.
Ок. Пройденный этап.
После этого мы решили, а почему бы не использовать тот же Fluentd в качестве агента.
Первый запуск Fluentd, при наличии большого числа файлов логов, оказался достаточно волнительным, так как в логе самого демона говорилось о том, что он видит только часть заданных ему файлов (и тут мы немного напряглись), при том, что когда его рестартуешь, он подхватывает разные файлы логов. Оказалось, это ожидаемое поведение, так как плагин tail является однопоточным и одновременно, он может осилить только 4 файла (видимо следуя здравому смыслу), выделяя какую-то часть времени на каждый файл и переключая контексты по истечению этого времени. Но после вычитки всех файлов — его поведение нормализуется.
Эта ситуация справедлива тогда, когда есть достаточно объемные файлы логов (как было в нашем случае) и с включенной опцией read_from_head (производить вычитку файла с самого начала). Если эту опцию не добавлять, то вычитка будет производиться по стандартному поведению tail, т.е. с конца файла.
Маршрутизация логов Fluentd производится на основании тэгов, т.е. каждый контейнер имеет свой тэг и если он совпадает с меткой на фильтре — производит его последовательную обработку (сверху вниз). По-умолчанию тэг присваивается вот такой:
|
1 |
<strong><span id="58da" class="mh mi ct bf ne b eh nf ng l nh" data-selectable-paragraph="">docker.<path_to_docker_logs>.<container_id>.<conteiner_id>-json.log</span></strong> |
В соответствии с тегом осуществляется фильтрация (например, если необходимо добавить какое-то поле в JSON лог или направить сразу на output).
Весь процесс выглядит следующим образом:
Fluentd вычитывает лог файл.
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
<source> @type tail @id in_tail_container_logs path /logs/docker_logs/*/*.log pos_file /data/docker.pos read_from_head true tag docker.** skip_refresh_on_startup false refresh_interval 10s enable_watch_timer true enable_stat_watcher false <parse> @type json time_format %Y-%m-%dT%H:%M:%S.%NZ </parse> </source> |
[/codesyntax]
Маршрутизирует на основании тэгов (фильтрует). В данном случае дописывает имя хостовой системы, на которой запущен контейнер.
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 |
<filter docker.**> @type record_transformer enable_ruby <record> hostname "#{Socket.gethostname}" </record> </filter> |
[/codesyntax]
Выполняет разбивку на порции данных (chunks ) и пишет их в буфер (buffer), который находится на диске. Порции данных помещает в очередь. Отправляет коллектору.
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
<match docker.**> @type forward @id forward_docker <server> name main_server host collector.example.com port 24224 </server> <buffer> @type file path /data/buffers/containers flush_mode interval retry_type exponential_backoff flush_thread_count 2 flush_interval 2s retry_forever retry_max_interval 30 chunk_limit_size 4M queue_limit_length 512 overflow_action block </buffer> </match> |
[/codesyntax]
Если TCP сокет коллектора не доступен — продолжает читать файл и аккуратно складывает порции данных до установленного предела, достиг предела, останавливает чтение файла и запоминает позицию. Связь возобновилась — ок, начинает передачу собравшихся данных и возобновляет чтение файла с места остановки.
Вот так выглядит сформированный формат JSON лога, который получается в итоге на выходе для передачи на коллектор:
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
2018-10-05 07:31:29.069710307 +0000 docker.logs.docker_logs.93f5b2302f7c91e5a6de695ec29ee125db2835fd29f1f861bbe5153f4ce7878c.93f5b2302f7c91e5a6de695ec29ee125db2835fd29f1f861bbe5153f4ce7878c-json.log: {"log":"[05/Oct/2018:07:31:25 +0000] "example.com" "1.2.3.4" "304" "0.002" "0.002" "443" "GET /default.css HTTP/1.1" "https://example.com/efk" "Mozilla/5.0", "stream":"stdout", "attrs":{"container_name":"example-nginx", "service":"nginx"}, "hostname":"host.example.com"}" |
[/codesyntax]
Итак разобрались с тем, что происходит на клиенте.
Коллектор
Теперь рассмотрим, что происходит на коллекторе.
Стрим поступает на TCP сокет коллектора и начинает процесс маршрутизации (фильтрации), и проходит следующий воркфлоу.
Попадает на цепочку docker_before — данная цепочка предназначена для переопределения тегов входящих логов от Docker контейнеров. Каждый контейнер имеет дополнительные атрибуты, такие как “attrs.service” и “attrs.container_name”. Переопределение тега происходит на основании “attrs.service”, например nginx. Все остальное, например, нам нет необходимости собирать логи с контейнера mongodb, все что нам нужно это убрать его из цепочки определения сервиса и он просто упадет в null. Выглядит вот так:
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 9 10 11 |
<match docker.logs.**> @type rewrite_tag_filter <rule> key $[‘attrs’][‘service’] pattern ^nginx$ tag docker.nginx </rule> </match> <match docker.logs.**> @type null </match> |
[/codesyntax]
Далее, выполняется маршрутизация (фильтрация) на основании переопределенного тега “docker.nginx” и попадает в следующий конфиг файл.
Nginx_common — данная цепочка выполняет разбивку логов на error и access на основании JSON поля “stream” и переопределяет тэги на “docker.nginx.stdout” и “docker.nginx.stderr”. Дальнейшее продвижение лога происходит на основании уже переопределенных тэгов.
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
<match docker.nginx> @type rewrite_tag_filter <rule> key stream pattern /stdout/ tag docker.nginx.stdout </rule> <rule> key stream pattern /stderr/ tag docker.nginx.stderr </rule> </match> |
[/codesyntax]
Далее происходит матчинг по тэгу “docker.nginx.stdout” и применяет к нему парсер с определенным форматом.
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 |
<filter docker.nginx.stdout> @type parser key_name log reserve_data true time_parse true format /^\[(?<time>.*)\]\s"(?<request_host>.*)"\s"(?<remote_host>.*)"\s"(?<status>\d{3})"\s"(?<request_time>\d+.\d+)"\s"(?<upstream_response_time>.*)"\s"(?<bytes_sent>.*)"\s"(?<method>\w{3,7})\s(?<request_uri>.*)\s(?<http_version>.*)"\s"(?<http_referer>.*)"\s"(?<http_user_agent>.*)"/ time_format %d/%b/%Y:%H:%M:%S %z </filter> |
[/codesyntax]
Далее модифицирует поле upstream_response_time (мы переопределяем значения некоторых полей (mapping)в Elasticsearch индексе для корректного поиска и фильтрации), чтобы поле содержало только цифирные значения, а не прочерки, если значение отсутствует.
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 |
<filter docker.nginx.stdout> @type record_transformer enable_ruby true auto_typecast true <record> upstream_response_time ${record["upstream_response_time"] == '-' ? -1.000 : record["upstream_response_time"]} </record> </filter> |
[/codesyntax]
Далее добавляем GeoIP данные, такие как “country_code”, “country_name”, “city” и “geoip_hash”.
Вот тут, кстати, заметили, что память “текла” при использовании библиотеки “geoip2_c”, поэтому выбрали “geoip2_compat”.
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
<filter docker.nginx.stdout> @type geoip geoip_lookup_keys remote_host geoip2_database "/opt/GeoLite2-City.mmdb" backend_library geoip2_compat <record> country ${country_code["remote_host"]} country_name ${country_name["remote_host"]} city ${city["remote_host"]} geoip_hash '[${longitude["remote_host"]},${latitude["remote_host"]}]' </record> skip_adding_null_record true </filter> |
[/codesyntax]
Так как поля “stream” и “log” мы распарсили, то смело можем их удалять. Поле “log” удаляем только с логов, тэгированных как “docker.nginx.stdout”, а поле “stream” удаляем со всех логов (это поле на основании, которого мы делали переопределение тэга в начале этой цепочки).
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 |
<filter docker.nginx.stdout> @type record_modifier remove_keys log </filter> <filter docker.nginx.*> @type record_modifier remove_keys stream </filter> |
[/codesyntax]
Парсим логи, тэгированные как “nginx.docker.stderr”. Тут вообще все просто, разбираем по минимуму: время, тип (severity type), pid, ну и собственно само тело сообщения (оставляем как есть).
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 |
<filter nginx.docker.stderr> @type parser key_name log reserve_data true format /^(?<time>.*)\s(?<type>\[\w+\])\s(?<pid>\d+#\d+):\s(?<log>[^ ].*)/ </filter> |
[/codesyntax]
Далее аккуратно раскладываем по индексам, предварительно, закидывая шаблон для индекса. Но, прежде чем отправить в индекс данные, они складываются порциями данных в буфер, который расположен на диске, попадают в очередь и сбрасываются порциями (bulk flush) каждые 5 с.
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 |
<match docker.nginx.stdout> @type elasticsearch logstash_format true logstash_prefix docker.nginx.stdout host elasticsearch port 9200 template_file /fluentd/etc/index_maps/docker.nginx.stdout template_name docker.nginx.stdout template_overwrite true max_retry_putting_template 15 request_timeout 15s reload_connections false <buffer> @type file path /buffers/docker.nginx.stdout flush_mode interval retry_type exponential_backoff flush_thread_count 2 flush_interval 5s retry_forever retry_max_interval 30 chunk_limit_size 2M queue_limit_length 100 overflow_action block </buffer> </match> <match docker.nginx.stderr> @type elasticsearch logstash_format true logstash_prefix docker.nginx.stderr host elasticsearch port 9200 template_file /fluentd/etc/index_maps/docker.nginx.stderr template_name docker.nginx.stderr template_overwrite true max_retry_putting_template 15 request_timeout 15s reload_connections false <buffer> @type file path /buffers/docker.nginx.stderr flush_mode interval retry_type exponential_backoff flush_thread_count 2 flush_interval 5s retry_forever retry_max_interval 30 chunk_limit_size 2M queue_limit_length 100 overflow_action block </buffer> </match> |
[/codesyntax]
На выходе из коллектора лог получается вот таким:
[codesyntax lang="php" blockstate="collapsed"]
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
2018-10-05 07:31:29.069710307 +0000 docker.nginx.stdout: {"attrs":{"container_name":"example-nginx", "service":"nginx"}, "hostname":"example.host.com", "request_host":"example.com", "remote_host":"1.2.3.4", "status":"304", "request_time":"0.002", "upstream_response_time":"0.002", "bytes_sent":"443", "method":"GET", "request_uri":"/default.css", "http_version":"HTTP/1.1", "http_referer":"-", "http_user_agent":"Mozilla/5.0", "country":"US", "country_name":"United States", "city":"Riverdale", "geoip_hash":[-84.4522,33.5561]} |
[/codesyntax]
Что касается настройки индекса в Elasticsearch, то мы изменяем параметр “number_of_shards: 1”, который по дефолту равен 5. Увеличивать количество шард (shard) есть смысл, когда собран кластер, так как при запросах Elasticsearch параллелит поиск по шардам в дата нодах, а так как дата нода у нас одна, то и количество шард должно быть равным количеству дата нод кластера.
Еще один параметр, который мы меняем это “number_of_replica: 0” — не держим реплику для Primary Shard, так как реплицировать, собственно говоря, и некуда.
В мапинге (mapping) индекса Elasticsearch мы изменяем типы следующих полей:
- bytes_sent — integer
- geoip_hash — geo_point
- remote_host — ip
- request_time — half_float
- status — short
- upstream_response_time — half_float