В этой статье я хочу рассказать о не совсем обычном использовании логов — о получении из лог-файлов метрик для Prometheus. Это может быть полезно, когда существующие экспортеры не предоставляют нужные метрики, а писать свой экспортер не хочется или очень затратно.
Один из наших клиентов пришел с задачей оперативно получать информацию о запросах из приложения к базе данных PostgreSQL, завершившихся с ошибкой, но не вносить при этом каких-либо изменений в кодовую базу приложения. Просмотрев существующие экспортеры для PostgreSQL и не найдя там подходящих метрик, по которым можно было бы отправить сообщение об ошибке, мы решили, что нужно самим сделать такую метрику.
Подготовка логов
Технически задача свелась к парсингу лог-файла, выделению метрики по полученным данным, записи метрики в Prometheus и настройки алертинга. К сожалению, PostgreSQL до 15 версии не поддерживает «из коробки» популярный формат структурированных логов JSON. Приносить для этого сторонние модули в production-окружение не хотелось, как и писать лог в формате CSV. Зато была возможность структурировать формат вывода в конфигурационном файле. Клиентом использовался следующий формат лога:
# postgresql.conf
log_line_prefix = '%m %p %u@%d from %h [vxid:%v txid:%x] [%i] 'Где:
%m– time stamp, включая миллисекунды;%p– Process ID;%u– имя пользователя;%d– имя базы данных.
Подробнее о том, за что отвечают другие переменные и какую еще информацию возможно записать в лог, написано в документации к PostgreSQL. В итоге получается приблизительно такая строка:
2022-05-12 07:33:54.285 UTC 2672031 @ from [vxid: txid:0] [] LOG: checkpoint complete: wrote 64 buffers (0.0%); 0 WAL file(s) added, 0 removed, 10 recycled; write=6.266
s, sync=0.004 s, total=6.285 s; sync files=10, longest=0.003 s, average=0.001 s; distance=163840 kB, estimate=163844 kBПоиск оптимального решения
Для получения метрики из логов и ее доставки в Prometheus мы пробовали использовать fluentd, promtail и Vector.
У fluentd существует обширная система плагинов на все случаи жизни. Например, есть fluent-plugin-prometheus для преобразования данных в формат метрик и доставки их в Prometheus. Однако после выпуска v2.0.0 в начале прошлого года проект развивается очень неторопливо. Поэтому, несмотря на то, что мы любим fluentd и часто его используем, в этот раз мы решили взять что-нибудь другое.
Первоначально выбор пал на promtail. Он умеет парсить текстовый файл лога (включая многострочные логи), обрабатывать его исходя из поставленной задачи (в том числе и выделять метрики), а также фильтровать содержимое по заданным параметрам.
Для теста был написан конфигурационный файл, в котором считались строчки лога. Вот пример стадии обработки лога:
pipeline_stages:
- multiline:
firstline: '^\[\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}\]'
- regex:
expression: '^(?P<time>\[\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}\]) (?P<message>(?s:.*))$'
- metrics:
log_lines_total:
type: Counter
description: "total number of log lines"
prefix: pg_custom_
max_idle_duration: 24h
config:
match_all: true
action: inc
log_bytes_total:
type: Counter
description: "total bytes of log lines"
prefix: pg_custom_
max_idle_duration: 24h
config:
match_all: true
count_entry_bytes: true
action: addКонфигурация прекрасно работала, однако мы упустили один важный момент. Promtail требует обязательным параметром в конфигурации указание адреса Loki — инструмента для агрегации логов, разрабатываемого Grafana. Без указания этого параметра он просто не запускается. Устанавливать клиенту еще и Loki нам показалось нецелесообразным.
Если очень хочется все-таки использовать promtail, можно вместо Loki указать адрес любого веб-сервера (например, nginx), который на любой запрос будет отдавать код ответа 200. Однако использовать подобный хак в production-окружении мы не рекомендуем.
Последним мы попробовали Vector, и он нам подошел.
Парсинг логов и их отправка в Prometheus с помощью Vector
Для того, чтобы получать данные от Vector в Prometheus, необходимо установить его на хосты, где находятся лог-файлы, которые нужно парсить, а затем настроить конфигурацию. Сделать это можно, например, с помощью Ansible:
# playbook-vector.yaml
---
- name: Setup vector
hosts:
- pg
become: yes
vars:
arch: amd64
version: 0.18.1
vector_template: files/40-vector.toml
vector_config_file: /etc/vector/vector.toml
tasks:
- name: Setup install vector
become: yes
apt:
deb: "https://packages.timber.io/vector/{{ version }}/vector-{{ version }}-{{ arch }}.deb"
install_recommends: yes
notify:
- restart vector
- name: Copy config
copy:
src: "{{ vector_template }}"
dest: "{{ vector_config_file }}"
mode: 0644
owner: vector
group: vector
notify: restart vector
- name: Start Vector
service:
state: started
enabled: yes
name: vector
handlers:
- name: restart vector
service:
state: restarted
daemon_reload: yes
name: vectorVector настраивается с помощью конфигурационного файла в формате TOML. Укажем, откуда будет читаться лог-файл, и его тип:
# vector.toml
[sources.postgres_logs.multiline]
start_pattern = '^\d{4}-[0-1]\d-[0-3]\d \d+:\d+:\d+\.\d+ [A-Z]{3}'
mode = "halt_before"
condition_pattern = '^\d{4}-[0-1]\d-[0-3]\d \d+:\d+:\d+\.\d+ [A-Z]{3}'
timeout_ms = 1000Мод halt_before означает, что Vector будет считать все последующие строки после condition_pattern, не начинающиеся с него, одним сообщением.
Существуют и другие варианты multiline.mode — например, half_with, когда в сообщение включаются все последовательные строки вплоть до первой строки, соответствующей шаблону condition_pattern.
Далее парсим сообщение, используя Vector Transform Language:
# vector.toml
[transforms.postgres_remap]
type = "remap"
inputs = [ "postgres_logs" ]
source = """
. |= parse_regex!(.message, r'^(?P<timedate>\\d{4}-[0-1]\\d-[0-3]\\d \\d+:\\d+:\\d+\\.\\d+ [A-Z]{3}) (?P<pid>\\d+) (?P<userdb>(\\[\\w+\\]@\\w+|@|\\w+@\\w+)) from (?P<ipaddr>(\\d{1,3}\\.\\d{1,3}\\.\\d{1,3}\\.\\d{1,3}|\\[\\w+\\]|\\s*)) (?P<txid>\\[\\w+:.+:\\d+\\]) (?P<trstate>(\\[\\]|\\[\\w.+\\])) (?P<level>.*[A-Z]): (?P<messages>.*)$')
del(.timestamp)
message_parts, err = split(.message, ", ", limit: 2)
structured = parse_key_value(message_parts[1], key_value_delimiter: ":", field_delimiter: ",") ?? {}
message = message_parts[0]
. = merge(., structured)
del(."please try the setup again")
del(.message)"""Здесь мы сделали следующее:
указали источник логов;
задали регулярное выражение, которым будем парсить сообщение лога;
удалили ненужные поля;
разбили сообщение по разделителю «, »;
записали результат в массив
map, обработали его и получили на выходе JSON, с полями которого можно работать дальше.
Теперь отфильтруем сообщения об ошибках:
# vector.toml
[transforms.postgres_filter]
type = "filter"
inputs = [ "postgres_remap" ]
condition = '.level == "ERROR" || .level == "FATAL"'Под фильтр попадают сообщения с уровнем, равным ERROR или FATAL.
Из отфильтрованных сообщений лога создаем метрику. Указываем тип метрики, поле, из которого она будет браться, даем ей понятное имя и навешиваем дополнительные лейблы.
# vector.toml
[transforms.postgres_metric]
type = "log_to_metric"
inputs = [ "postgres_filter" ]
[[transforms.postgres_metric.metrics]]
type = "counter"
field = "level"
name = "error_total"
namespace = "pg_log"
[transforms.postgres_metric.metrics.tags]
level = "{{level}}"
host = "{{host}}"На последнем этапе публикуем экспортер, откуда Prometheus будет забирать наши метрики.
[sinks.postgres_export_metric]
type = "prometheus_exporter"
inputs = [ "postgres_metric" ]
address = "0.0.0.0:9598"
default_namespace = "pg_log"Настройка алертинга на основании полученных метрик
Для получения метрик с нового экспортера настраиваем обычный target в Prometheus:
scrape_configs:
- job_name: custom-pg-log-exporter
static_configs:
- targets: ['10.10.10.2:9598', '10.10.10.3:9598', '10.10.10.4:9598']Теперь на основе полученной метрики создаем правило, которое Alertmanager будет обрабатывать согласно настройкам своей маршрутизации:
- alert: PgErrorCountChangeWarning
expr: |
increase(pg_log_error_total{level="ERROR"}[30m]) > 0
for: 10m
labels:
severity: warning
annotations:
summary: The amount of errors in pg host {{$labels.host}} log has changed to {{$value}}
description: |
Появились ошибки в логах PostgreSQL на сервере {{$labels.host}}.
- alert: PgErrorCountChangeCritical
expr: |
increase(pg_log_error_total{level="FATAL"}[30m]) > 0
for: 10m
labels:
severity: critical
annotations:
summary: The amount of fatal errors in pg host {{$labels.host}} log has changed to {{$value}}
description: |
Появились фатальные ошибки в логах PostgreSQL на сервере {{$labels.host}}.Здесь мы вычисляем прирост временного ряда вектора значений pg_log_error_total за 30 минут. Если это значение больше нуля — счетчик изменился, отправляем алерт, после чего его получатель может смотреть в логи PostgreSQL, что же именно там произошло.
Заключение
Мы рассмотрели на примере простого счетчика ошибок, как можно настроить сбор метрик из текстового лога. Если нужные метрики не предоставляются существующими экспортерами и нет возможности менять код приложения, это может быть сравнительно простым выходом из положения.
Кроме удобства конфигурирования на наш выбор повлияли широкие возможности Vector, которые позволяют широко его использовать для различных задач, и его высокая производительность для более эффективного использования имеющихся ресурсов. Для отладки пайплайнов лога и просмотра метрик самого Vector можно использовать CLI-утилиту vector top, которая выводит информацию в красивом TUI-интерфейсе.
Помимо простого счетчика Vector можно настроить и для парсинга логов медленных запросов базы данных, после чего обработать их с помощью VRL, агрегировать, перевести в метрику и выводить, например, топ 10 запросов в Grafana. А для аудита по безопасности — собирать логи подключений, создавая метрики на основании полученных данных. В общем, применений может быть множество, и тут все зависит от существующих потребностей.
Мы также выбрали Vector для своей платформы Deckhouse (модуль log-shipper), доверив ему доставку логов из Pod’ов Kubernetes-кластеров в одно из хранилищ (Loki, Elasticsearch или Logstash). А по мере необходимости и возможности — даже участвуем в разработке этого проекта.
P.S.
Читайте также в нашем блоге:
