Мы в Домклик много лет используем ELK-stack (сейчас уже OpenSearch) для хранения и работы с логами, которых у нас очень много: около 400 гигабайтов в день. 400 гигов, Карл! Весь этот объём проходит через Logstash, где логи частично парсятся, обогащаются метаданными и т. д.
Недавно мы решили стандартизировать логи инфраструктурных сервисов, которые подняты в нескольких экземплярах. Начали с HAproxy. У нас несколько групп экземпляров под разные цели, с разным количеством логов. Раньше каждая группа HAproxy писала логи в каком-то собственном формате, и мы парсили эти логи с помощью всего одного паттерна для Grok-фильтра. Сообщение либо подходило под паттерн и разбивалось на поля, либо отправлялось в виде одной текстовой строки.
Расскажу о проблемах, с которыми мы столкнулись при добавлении новых Grok-паттернов, и о том, как мы их решили, отказавшись от Grok.
Неудачная попытка остаться на Grok
Для стандартизации логов мы написали пачку Grok-паттернов под самые разные сообщения, которые могла «выплюнуть» HAproxy. Получившийся фильтр выглядел так:
Скрытый текст
filter {
grok {
patterns_dir => "{{ logstash_conf_dir }}/patterns/"
keep_empty_captures => true
match => {
"message" => [
"%{HP_HTTP_MSG1}",
"%{HP_HTTP_MSG2}",
"%{HP_HTTP_MSG3}",
"%{HP_HTTP_MSG4}",
"%{HP_HTTP_MSG5}",
"%{HP_TCP_MSG1}",
"%{HP_LOG_MSG1}",
"%{HP_GLOBAL_MSG2}",
"%{HP_GLOBAL_MSG1}",
"%{HP_GLOBAL_MSG3}",
"%{HP_GLOBAL_MSG4}"
]
}
remove_field => "message"
}
date {
match => [ "log_time", "dd/MMM/yyyy:HH:mm:ss.SSS" ]
}
}Сами паттерны:
Скрытый текст
HP_TIME (?!<[0-9])%{HOUR}:%{MINUTE}(?::%{SECOND})(?![0-9])
HP_DATE %{MONTHDAY}/%{MONTH}/%{YEAR}:%{HP_TIME}.%{INT}
HP_FRONT %{DATA:[frontend_name]}
HP_BACK %{DATA:[backend_name]}
HP_SERVER_NAME %{DATA:[server_name]}
HP_TR %{NUMBER:[Tr_response_time]}
HP_TW %{NUMBER:[Tw_queues_waiting_connection]}
HP_TC %{NUMBER:[Tc_establish_tcp_connection]}
HP_TRF %{NUMBER:[TR_time_receive_full_request]}
HP_TA %{NUMBER:[Ta_total_request_time]}
HP_TT %{NUMBER:[Tt_total_time]}
HP_IP %{IPORHOST:[client_ip]}
HP_PORT %{NUMBER:[client_port]}
HP_STATUS_CODE %{NUMBER:[status_code]}
HP_BYTES_READ %{NUMBER:[bytes_read]}
HP_CAP_REQ_COOKIE %{DATA:[captured_request_cookie]}
HP_CAP_RES_COOKIE %{DATA:[captured_response_cookie]}
HP_TERM_STATE %{DATA:[termination_state_with_cookie_status]}
HP_ACT_CONN %{NUMBER:[active_connections]}
HP_FE_CONN %{NUMBER:[front_connections]}
HP_BE_CONN %{NUMBER:[back_connections]}
HP_SERVER_CONN %{NUMBER:[server_conn]}
HP_RETRIES %{NUMBER:[retries]}
HP_SRV_QUE %{NUMBER:[server_queue]}
HP_BACK_QUE %{NUMBER:[backend_queue]}
HP_CREQH %{DATA:[captured_request_headers]}
HP_CREQH_GREED %{GREEDYDATA:[captured_request_headers]}
HP_CRESH %{DATA:[captured_response_headers]}
HP_TERMINATION_STATE %{DATA:[termination_state]}
HP_HTTP_REQUEST %{WORD:[http_request_method]} %{DATA:[url_original]} HTTP/%{DATA:[http_version]}
HP_HTTP_REQUEST_STRIPPED %{WORD:[http_request_method]} %{DATA:[url_original]}
HP_LOG %{GREEDYDATA:[log]}
HP_LOG_LEVEL %{DATA:[log_level]}
HP_STATE %{DATA:[state]}
HP_REASON %{DATA:[reason]}
HP_CHECK_DUR %{DATA:[check_duration]}
HP_ACT_SERVS %{NUMBER:[active_servers_online]}
HP_BACKUP_SERVS %{NUMBER:[backup_servers_online]}
HP_SESS_REQ %{NUMBER:[sessions_requeued]}
HP_TOTAL_QUE %{NUMBER:[total_in_queue]}
HP_PID %{NUMBER:[pid]}
HP_LOGS_WORD_START proxy|backend|Proxy
HP_HTTP_MSG1 %{HP_IP}:%{HP_PORT} \[%{HP_DATE:[log_time]}\] %{HP_FRONT} %{HP_BACK}/%{HP_SERVER_NAME} %{HP_TRF}/%{HP_TW}/%{HP_TC}/%{HP_TR}/%{HP_TA} %{HP_STATUS_CODE} %{HP_BYTES_READ} %{HP_CAP_REQ_COOKIE} %{HP_CAP_RES_COOKIE} %{HP_TERM_STATE} %{HP_ACT_CONN}/%{HP_FE_CONN}/%{HP_BE_CONN}/%{HP_SERVER_CONN}/%{HP_RETRIES} %{HP_SRV_QUE}/%{HP_BACK_QUE} \{%{HP_CREQH}\} \{%{HP_CRESH}\} "%{HP_HTTP_REQUEST}"
HP_HTTP_MSG2 %{HP_IP}:%{HP_PORT} \[%{HP_DATE:[log_time]}\] %{HP_FRONT} %{HP_BACK}/%{HP_SERVER_NAME} %{HP_TRF}/%{HP_TW}/%{HP_TC}/%{HP_TR}/%{HP_TA} %{HP_STATUS_CODE} %{HP_BYTES_READ} %{HP_CAP_REQ_COOKIE} %{HP_CAP_RES_COOKIE} %{HP_TERM_STATE} %{HP_ACT_CONN}/%{HP_FE_CONN}/%{HP_BE_CONN}/%{HP_SERVER_CONN}/%{HP_RETRIES} %{HP_SRV_QUE}/%{HP_BACK_QUE} \{%{HP_CREQH}\} "%{HP_HTTP_REQUEST}"
HP_HTTP_MSG3 %{HP_IP}:%{HP_PORT} \[%{HP_DATE:[log_time]}\] %{HP_FRONT} %{HP_BACK}/%{HP_SERVER_NAME} %{HP_TRF}/%{HP_TW}/%{HP_TC}/%{HP_TR}/%{HP_TA} %{HP_STATUS_CODE} %{HP_BYTES_READ} %{HP_CAP_REQ_COOKIE} %{HP_CAP_RES_COOKIE} %{HP_TERM_STATE} %{HP_ACT_CONN}/%{HP_FE_CONN}/%{HP_BE_CONN}/%{HP_SERVER_CONN}/%{HP_RETRIES} %{HP_SRV_QUE}/%{HP_BACK_QUE} "%{HP_HTTP_REQUEST}"
HP_HTTP_MSG4 %{HP_IP}:%{HP_PORT} \[%{HP_DATE:[log_time]}\] %{HP_FRONT} %{HP_BACK}/%{HP_SERVER_NAME} %{HP_TRF}/%{HP_TW}/%{HP_TC}/%{HP_TR}/%{HP_TA} %{HP_STATUS_CODE} %{HP_BYTES_READ} %{HP_CAP_REQ_COOKIE} %{HP_CAP_RES_COOKIE} %{HP_TERM_STATE} %{HP_ACT_CONN}/%{HP_FE_CONN}/%{HP_BE_CONN}/%{HP_SERVER_CONN}/%{HP_RETRIES} %{HP_SRV_QUE}/%{HP_BACK_QUE} "%{HP_HTTP_REQUEST_STRIPPED}
HP_HTTP_MSG5 %{HP_IP}:%{HP_PORT} \[%{HP_DATE:[log_time]}\] %{HP_FRONT} %{HP_BACK}/%{HP_SERVER_NAME} %{HP_TRF}/%{HP_TW}/%{HP_TC}/%{HP_TR}/%{HP_TA} %{HP_STATUS_CODE} %{HP_BYTES_READ} %{HP_CAP_REQ_COOKIE} %{HP_CAP_RES_COOKIE} %{HP_TERM_STATE} %{HP_ACT_CONN}/%{HP_FE_CONN}/%{HP_BE_CONN}/%{HP_SERVER_CONN}/%{HP_RETRIES} %{HP_SRV_QUE}/%{HP_BACK_QUE} \{%{HP_CREQH_GREED}
HP_TCP_MSG1 %{HP_IP}:%{HP_PORT} \[%{HP_DATE:[log_time]}\] %{HP_FRONT} %{HP_BACK}/%{HP_SERVER_NAME} %{HP_TW}/%{HP_TC}/%{HP_TT} %{HP_BYTES_READ} %{HP_TERMINATION_STATE} %{HP_ACT_CONN}/%{HP_FE_CONN}/%{HP_BE_CONN}/%{HP_SERVER_CONN}/%{HP_RETRIES} %{HP_SRV_QUE}/%{HP_BACK_QUE}
HP_LOG_MSG1 %{HP_IP}:%{HP_PORT} \[%{HP_DATE:[log_time]}\] %{HP_LOG}
HP_GLOBAL_MSG1 Server %{HP_BACK}/%{HP_SERVER_NAME} is %{HP_STATE},%{SPACE}%{HP_LOG}
HP_GLOBAL_MSG2 \[%{HP_LOG_LEVEL}\]%{SPACE}\(%{HP_PID}\)%{SPACE}:%{SPACE}%{HP_GLOBAL_MSG1}
HP_GLOBAL_MSG3 \[%{HP_LOG_LEVEL}\]%{SPACE}\(%{HP_PID}\)%{SPACE}:%{SPACE}%{HP_LOG}
HP_GLOBAL_MSG4 %{HP_LOGS_WORD_START}%{SPACE}%{HP_LOG}Включили эту конфигурацию на HAproxy № 1, которая пишет около 2 тыс. сообщений в минуту. Всё заработало, все радовались и хлопали в ладоши. Правда, вырос график, показывающий длительность фильтрации сообщений:
На него не сразу обратили внимание, потому что логи попадали в OpenSearch с прежней скоростью. А зря, ведь длительность обработки выросла в 3–4 раза!
Пошли пробовать на HAproxy № 2, которая пишет уже 120 тыс. сообщений в минуту. Тут-то нас и ждало разочарование: после включения настроек длительность фильтрации улетела в космос, увеличившись более чем в 40 раз!
Скорость обработки упала до 20 тыс. сообщений в минуту:
Попытались увеличить количество worker'ов на Logstash. Раньше справлялся один, выставили 12. Потребление процессора выросло на 12 ядер, скорость обработки сообщений выросла до 100 тыс. в минуту, но этого всё равно было мало, а ресурсы на Logstash кончились. Стало понятно, что так жить нельзя, Grok слишком прожорливый по ресурсам. Откатили конфигурацию и пошли думать, как можно решить проблему, не покупая ещё несколько VM под Logstash.
Решение — фильтр Dissect
Так как парсить надо, но Grok не подходит, решили посмотреть, а какие вообще есть фильтры в Logstash? И обнаружили Dissect. Это фильтр-токенизатор. Токенизация — процесс, когда неструктурированные данные обрабатываются в соответствии с шаблоном, ориентируясь на разделители в этом самом шаблоне.
Dissect в разы быстрее Grok, но есть и ложка дёгтя: Dissect не умеет в регулярные выражения, не распознаёт типы данных и не поддерживает множественные паттерны (шаблон всегда один). В официальной документации рекомендуют его использовать, когда данные надёжно повторяются. Дело в том, что если строка не подходит под шаблон хотя бы одним полем или символом, то не будет обработан весь лог.
Набросали конфигурацию без использования Grok, полностью на Dissect. Читабильность сильно ухудшилась, но что поделать:
Скрытый текст
filter {
dissect {
mapping => {
"message" => "%{client_ip}:%{client_port} [%{log_time}] %{log_text}"
}
}
if [log_text] {
dissect {
mapping => {
"log_text" => "%{frontend_name} %{backend_name}/%{server_name} %{TR_time_receive_full_request}/%{Tw_queues_waiting_connection}/%{Tc_establish_tcp_connection}/%{Tr_response_time}/%{Ta_total_request_time} %{status_code} %{bytes_read} %{captured_request_cookie} %{captured_response_cookie} %{termination_state_with_cookie_status} %{active_connections}/%{front_connections}/%{back_connections}/%{server_conn}/%{retries} %{server_queue}/%{backend_queue} %{http1}"
}
}
}
if [log_text] and "_dissectfailure" in [tags] {
dissect {
remove_tag => ["_dissectfailure"]
mapping => {
"log_text" => "%{frontend_name} %{backend_name}/%{server_name} %{Tw_queues_waiting_connection}/%{Tc_establish_tcp_connection}/%{Tt_total_time} %{bytes_read} %{termination_state} %{active_connections}/%{front_connections}/%{back_connections}/%{server_conn}/%{retries} %{server_queue}/%{backend_queue}"
}
}
}
if [log_text] and "_dissectfailure" in [tags] {
dissect {
remove_tag => ["_dissectfailure"]
mapping => {
"log_text" => "%{log_message}"
}
}
}
if "_dissectfailure" in [tags] {
dissect {
mapping => {
"message" => "%{log_message}"
}
}
}
if [http1] {
dissect {
remove_tag => ["_dissectfailure"]
mapping => {
"http1" => '%{captured_request_headers} %{captured_request_headers} "%{http_request_method} %{url_original} HTTP/%{http_version}"'
}
}
}
if [http1] and "_dissectfailure" in [tags] {
dissect {
remove_tag => ["_dissectfailure"]
mapping => {
"http1" => '%{captured_request_headers} "%{http_request_method} %{url_original} HTTP/%{http_version}"'
}
}
}
if [http1] and "_dissectfailure" in [tags] {
dissect {
remove_tag => ["_dissectfailure"]
mapping => {
"http1" => '%{captured_request_headers} "%{http_request_method} %{url_original}'
}
}
}
if [http1] and "_dissectfailure" in [tags] {
dissect {
remove_tag => ["_dissectfailure"]
mapping => {
"http1" => '"%{http_request_method} %{url_original} HTTP/%{http_version}"'
}
}
}
if [http1] and "_dissectfailure" in [tags] {
dissect {
remove_tag => ["_dissectfailure"]
mapping => {
"http1" => '"%{http_request_method} %{url_original}'
}
}
}
if [http1] and "_dissectfailure" in [tags] {
dissect {
remove_tag => ["_dissectfailure"]
mapping => {
"http1" => "%{captured_request_headers}"
}
}
}
date {
match => [ "log_time", "dd/MMM/yyyy:HH:mm:ss.SSS" ]
}
mutate {
remove_field => ["message"]
remove_field => ["log_text"]
remove_field => ["http1"]
}
}И оно заработало! Длительность обработки выросла всего в 2 раза, с учётом того, что так и остался один worker, а мы добавили около 10 дополнительных паттернов. Напомню, с аналогичной конфигурацией на Grok скорость фильтрации замедлилась в 40 раз!
Осталось закрепить успех. Проверяем фильтр на HAproxy №3, которая пишет целых 1,5 млн сообщений в минуту! Это около 25 тыс. сообщений в секунду. Фильтрация через Grok занимала около 3 сек:
А через Dissect — до 5 сек. Отличный результат! Повторюсь, мы добавили 10 дополнительных паттернов в обработку. Увеличение времени фильтрации ожидаемо. Если бы включили те же паттерны через grok, время обработки было бы в разы выше, как в примере с HAproxy №2.
Выводы
Dissect — хорошая альтернатива Grok. Он в разы производительнее за счёт того, что фильтрация происходит не на основе регулярных выражений. Особенно хорошо фильтр подходит для повторяющихся данных, но даже если они различаются, можно написать большую, страшную конфигурацию, которая будет выполнять обработку.
Grok — сильно гибче, удобнее, проще, но, к сожалению, за эти плюсы приходится расплачиваться огромными вычислительными ресурсами. Безусловно, при маленькой нагрузке (или если вы очень богаты), можно и нужно пользоваться Grok.
AnyKey80lvl
Интересно было бы попробовать грок, но в регулярки добавить в начало ^, где это применимо. Делем так в 99 процентах случаев при парсинге логов. Есть мнение, что это весьма ускоряет регулярки.
Ещё смутил параметр
keep_empty_captures, интересен сценарий его использования.Но dissect будет всегда быстрее - это бесспорно.
stinker Автор
Про ^ для регулярок интересно, попробую как нибудь.
keep_empty_captures - по сути да, не нужная настройка. Тестировали ее, когда настраивали Grok.