В этой статье я хочу рассказать о не совсем обычном использовании логов — о получении из лог-файлов метрик для 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: vector

Vector настраивается с помощью конфигурационного файла в формате 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.

Читайте также в нашем блоге:

• «Логи в Kubernetes (и не только) сегодня: ожидания и реальность»;

• «Мониторинг PostgreSQL. Расшифровка аудиочата Data Egret и Okmeter»;

• «Мониторинг и Kubernetes» (обзор и видео доклада).