Доброго дня, коллеги и хаброчитатели! Сегодня, хотел бы поделиться с Вами небольшой заметкой о том, как можно организовать оперативный мониторинг ошибок и событий появляющихся в журнале PostgreSQL используя Prometheus и экспортер метрик grok_exporter.

Сразу оговорюсь, что это конечно же частный случай использования данного экспортера. Так для чего это нужно и кому это может быть интересно?

Введение

Кому это нужно?

Если в Вашей инфраструктуру уже присутствует Prometheus и создавать отдельную инфраструктуру сбора и анализа логов, вроде ELK или Greylog, накладно и нецелесообразно (если Prometheus отсутствует, это не беда, ставится просто и быстро).

Инструмент будет полезен не только DBA, но и администраторам приложений, в общем всем тем кто так или иначе работает с логами приложений. Он позволяет оперативно получить информацию о внештатном поведении и иметь некую точку отсчета, для дальнейшего разбора ситуации.

Для чего это всё нужно?

Мониторинг журналов позволит иметь более полную картину и оперативнее реагировать на возникающие проблемы, будь то: попытки авторизации (в том числе не удачные), различные ошибки или конкретные события.

Здесь есть неплохой список, сформированный по категориям событий (См. раздел Log Event Categories), его можно использовать для создания правил в Prometheus.

grok_exporter

Экспортер метрик grok_exporter позволяет читать из источника неструктурированные данные, преобразовывая их в структурированные, согласно правилам и отдавать их, как метрики в формате понятном Prometheus.

Экспортер создан по образу и подобию плагина в ELK plugins-filters-grok, что позволяет использовать набор шаблонов plugins-filters-grok, как они есть.

Установка

Установка является мероприятием незамысловатым и простым. Для этого, достаточно перейти по ссылке и скачать приглянувшуюся версию (и да они все pre-release, а последние версии еще в стадии release candidate) и распаковать полученный архив.

В результате, получим такой набор:

grok_exporter-1.0.0.RC3.linux-amd64
├── patterns
│   ├── ruby
│   ├── redis
│   ├── rails
│   ├── postgresql
│   ├── nagios
│   ├── mongodb
│   ├── mcollective-patterns
│   ├── mcollective
│   ├── linux-syslog
│   ├── junos
│   ├── java
│   ├── haproxy
│   ├── grok-patterns
│   ├── firewalls
│   ├── exim
│   ├── bro
│   ├── bacula
│   └── aws
├── grok_exporter
└── example
    ├── exim-rejected-RCPT-examples.log
    ├── config.yml
    └── config_logstash_http_input_ipv6.yml

, где:

grok_exporter — исполняемый файл экспортера
patterns — содержит набор шаблонов
example — содержит тестовый набор данных и пример файла конфигурации

Для начала работы экспортера, достаточно запустить исполняемый файл. Файл конфигурации config.yml ищется в директории откуда запущено приложение или его расположение задается опцией -config

Настройка и подготовка к работе

PostgreSQL

Предварительно, необходимо настроить логирование в самом PostgreSQL. А именно:

Вынести журналы в доступное для grok_exporter место и установить привилегии. Перезапуск экземпляра не требуется, достаточно вызвать pg_reload_conf.
- ```
alter system set log_directory to '/var/log/postgresql'; 
```
- ```
alter system set log_file_mode to '0644';
```
Настроить log_line_prefix, по вкусу. Это необходимо для получения детальной информации, иначе будет куча мусора. Как вариант:
```
 alter system set log_line_prefix to '%t datname:%d,client:%h,app:%a,usename:%u,session:%c ';
```

grok_exporter

В первую очередь, отредактируем шаблон patterns/postgresql в соответствии с форматом нашего лог-файла и добавим вспомогательные конструкции. Ещё раз подчеркну, что синтаксис шаблонов полностью соответствует применяемому в plugins-filters-grok, по этому, по всем вопросам связанным синтаксисом, можно и нужно ходить в его документацию. Итак приведём наш шаблон для PostgreSQL к виду (в файле patterns/grok-patterns уже содержится большой набор базовых шаблонов):

# Формат даты как в лог-файле postgresql
PG_TIMESTAMP %{YEAR}-%{MONTHNUM}-%{MONTHDAY} %{HOUR}:%{MINUTE}:%{SECOND} [A-Z]{3,4}

# Список префиксов означающих ошибку
PG_ERROR_PATTERN (ERROR|WARNING|FATAL|PANIC)

# log_line_prefix однозначно идентифицирующий лог-файл PostgreSQL
PG_PREFIX %{PG_TIMESTAMP} datname:(%{DATA:datname})?,client:(%{DATA:client_host})?,app:(%{DATA:app_name})?,usename:(%{USER:usename})?,session:(%{DATA:session})?

# Добавляем возможность использовать log_level в качестве метки в метриках
PG_ERROR_LEVEL %{PG_ERROR_PATTERN:log_level}:

# Идентифицируем событие успешной авторизации
PG_EVENT_AUTH LOG:  connection authorized:

# Идентифицируем событие получения сигнала  SIGHUP, для перечитывания конфигурации
PG_EVENT_RELOAD LOG:  received SIGHUP, reloading configuration files

Конструкция ()? позволяет указывать, что значение опционально.

Здесь достаточно подробно, с примерами, описан процесс создания файла конфигурации. Ниже, приведено только то что будет использовано.

Краткое описание файла конфигурации (из документации)

Файл конфигурации представляет собой файл в YAML формате и разбит на секции:

global — глобальные настройки
- config_version — версия файла конфигурации. Зависит от версии grok_exporter, для версии ≥ 1.0.0.RC3, необходимо указывать 3
  retention_check_interval — интервал проверки актуальности метрики. Штука нужная для счетчиков, подробности будут ниже.
input — описывает источник получения неструктурированных данных и способ его обработки.
- type — тип источника данных. Допустимые значения: file, stdin, webhook. В нашем случае, будем рассматривать только file;
- path|paths — cодержит путь либо массив путей к лог-фалу(-ам). Допускается использование маски;
- readall — флаг, указывает на то как будет читаться файл.
  Если true — файл будет разобран от начала, рекомендуется только в случае отладки. Загрузить таким образом исторические данные в Prometheus невозможно.
  Если false — экспортер будет обрабатывать только те данные, которые были записаны в файл после запуска grok_exporter;
- fail_on_missing_logfile — определяет поведение приложения в случае отсутствия файла-источника. Если true — то приложение завершит работу, в случае отсутствия источника;
imports — секция, позволяет включать шаблоны, а так же загружать информацию о метриках из отдельных файлов. В версии конфигурации 2, допускалась загрузка только шаблонов, в секции grok.
- type — определяет тип загружаемого файла grok_patterns (шаблоны) или metrics (метрики);
- file|dir — тип источника. Загрузить из файла и загрузить из всех файлов в директории, соответственно.
grok_patterns — секция, позволяет задать новые или переопределить заданные в файлах шаблоны.
metrics — содержит описание собираемых метрик. Поддерживаемые типы — counter, gauge, histogram, or summary.

server — содержит настройки сетевого подключения

  protocol: https
  host: localhost
  port: 9144
  path: /metrics
  cert: /path/to/cert
  key: /path/to/key

В синтаксисе 3-й версии файла конфигурации, появилась возможность импортировать метрики из отдельных файлов, это позволит группировать метрики по назначению.

Далее, создадим базовый файл конфигурации config.yml. В нем, мы: задаём путь к лог-файлам PostgreSQL по маске; импортируем шаблоны из директории patterns и метрики из директории metrics.d; указываем по какому протоколу и на каком порту необходимо обращаться за метриками.

config.yml

  config_version: 3
  retention_check_interval: 10s
input:
  type: file
  path: /var/log/postgresql/postgresql-*.log
  readall: false
imports:
- type: grok_patterns
  dir: ./patterns
- type: metrics
  dir: ./metrics.d
server:
  protocol: http
  port: 9144

Теперь, создадим директорию metrics.d и разместим в ней файл postgresql.yml, в котором и опишем тестовый набор метрик.

Стоит отметить, что каждая метрика имеет свой срок жизни, т.е. если в течении заданного интервала времени (задается в retention, по-умолчанию 2 часа 30 минут) значение метрики не изменилось, то она считается устаревшей. Все устаревшие метрики удаляются через интервал времени retention_check_interval.

Так же, из особенностей:

Если метрика не изменялась и не является истекшей, она вернёт последнее значение независимо от указанного типа;
Из первой особенности следует вторая — метрики типа GAUGE и COUNTER, ведут себя одинаково. Т.е. если метрика объявлена как GAUGE, то её значение не будет сброшено при следующей проверке;
Если значение cumulative установлено в true, будет производится суммирование значений метрик с одинаковым набором меток (label), что является ожидаемым поведением. Неожиданным может стать ситуация, когда при втором запросе можно получить сумму значений в запросе плюс предыдущее значение.
Если значение cumulative установлено в false, при наличии метрик с одинаковым набором меток, будет выведено только последнее значение;

Букв получилось много, путано и местами непонятно, но попробую раскрыть это в примерах ниже.

И так, у нас есть файл конфигурации, который может возвращать четыре метрики три счетчика и одно произвольное значение. По сути первые три считают количество совпадений поля шаблона match со строками полученными от источника, четвертое — выводит сумму величин.

postgresql.yaml

# Счетчик кол-ва ошибок
- type:   counter
  name:   pg_grok_error_count
  help:   Count of line error
  match:  '%{PG_PREFIX} %{PG_ERROR_LEVEL}  %{GREEDYDATA:message}'
  labels:
    log_level:   '{{.log_level}}'
    usename:     '{{.usename}}'
    datname:     '{{.datname}}'
    app_name:    '{{.app_name}}'
    client_host: '{{.client_host}}'
    message:     '{{.message}}'

# Счетчик удачных авторизаций
- type:   counter
  name:   pg_grok_auth_succes_count
  help:   Count of connections authorized
  match:  '%{PG_PREFIX} %{PG_EVENT_AUTH}'
  labels:
    usename:     '{{.usename}}'
    datname:     '{{.datname}}'
    app_name:    '{{.app_name}}'
    client_host: '{{.client_host}}'

# Счетчик обновлений конфигурации
- type:   counter
  name:   pg_grok_reload_conf_count
  help:   Count of call pg_reload_conf
  match:  '%{PG_PREFIX} %{PG_EVENT_RELOAD}'
  labels:
    session:     '{{.session}}'

# Размер временных файлов
- type:       gauge
  name:       pg_grok_tpm_file_size_bytes
  help:       Size of tmp file created by time
  match:      '%{PG_PREFIX} %{PG_EVENT_TMP_FILE}'
  value:      '{{.size}}'
  cumulative: true
  retention:  5s
  labels:
    static:     'temp_file'

Практика

pg_grok_error_count

Метрика подсчитывает количество событий ERROR, WARNING, FATAL и PANIC, согласно шаблона. Может быть полезна для мониторинга и оповещения при внештатных ситуациях. Например, можно настроить оповещение в случаях: попыток неудачной авторизации, превышения порога количества ошибок на единицу времени или когда база находится в состоянии восстановления после сбоя и многое другое (Log Event Categories).

Для примера настроим оповещение о неудачных попытках авторизации. Пример неудачной попытка авторизации, в лог-файле PostgreSQL выглядит так:

2020-04-20 23:34:53 AEST datname:test,client:127.0.0.1,app:[unknown],usename:test_user,session:5e9da4fd.733 FATAL:  password authentication failed for user "test_user"
2020-04-20 23:34:53 AEST datname:test,client:127.0.0.1,app:[unknown],usename:test_user,session:5e9da4fd.733 DETAIL:  Password does not match for user "test_user".
        Connection matched pg_hba.conf line 86: "host    all             all             127.0.0.1/32            md5"

В выводе grok_exporter неудачные попытки авторизации можно идентифицировать по метке message содержащей подстроку password authentication failed for...:

pg_grok_error_count{app_name="[unknown]",client_host="127.0.0.1",datname="postgres",log_level="FATAL",message="password authentication failed for user "postgres"", usename="postgres"} 15
pg_grok_error_count{app_name="[unknown]",client_host="127.0.0.1",datname="test",log_level="FATAL",message="password authentication failed for user \"test_user\"",usename="test_user"} 5

Полученные данные помогут сформировать правило для Prometheus. Чувствительность можно подстраивать исходя из собственных реалий

groups:
- name: AuthAlert
  rules:
  - alert: AuthFail
    expr: sum(rate(pg_grok_error_count{message=~"password authentication failed for user.*"}[1m])) by (instance) > 0.1
    for: 30s
    labels:
      severity: warning
    annotations:
      summary: Too many fail authorization for {{ $labels.instance }}

pg_grok_reload_conf_count

Аналогично, можно отслеживать выполнение команды pg_reload_conf. Причем, стоит обратить внимание на список меток, а точнее на то, что используется всего одна метка sessions. Это связано с тем, что событие создаётся в рамках серверного процесса, а не сеанса пользователя.

В лог-файле PostgreSQL это событие выглядит так:

2020-04-21 01:20:26 AEST datname:,client:,app:,usename:,session:5e9d9371.564 LOG:  received SIGHUP, reloading configuration files

Т.е. видно, что метки которыми пользовались в предыдущем примере — пустые. В этом случае для идентификации будем использовать идентификатор сессии, причем он не изменится до момента остановки или перезапуска экземпляра PostgreSQL.

Аналогичная ситуация будет и для других подобных случаев, например остановка экземпляра:

2020-04-21 01:32:52 AEST datname:,client:,app:,usename:,session:5e9d9371.564 LOG:  received fast shutdown request
2020-04-21 01:32:53 AEST datname:,client:,app:,usename:,session:5e9d9371.564 LOG:  database system is shut down

В выводе grok_exporter, получим:

# HELP pg_grok_reload_conf_count Count of call pg_reload_conf
# TYPE pg_grok_reload_conf_count counter
pg_grok_reload_conf_count{session="5e9d9371.564"} 5

Правило для оповещения, приводить нет смысла, оно будет аналогично рассмотренному выше.

pg_grok_tpm_file_size_bytes

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

На поведение gauge-метрик можно влиять изменяя параметры retention и cumulative. Ведь в отличии от обычного счетчика, который считает количество строк совпавших с шаблоном match, gauge позволяет оперировать данными из лог-файла. Получается, что мы можем накапливать его увеличивая или уменьшая на полученную величину, либо использовать как произвольно меняющуюся величину. Таким образом в первом случае, нас будет интересовать величина приращения, во втором — значение само по себе.

Рассмотрим несколько примеров:

Метрика должна содержать суммарное значение, для одинакового набора меток (cumulative: true). Значение должно характеризовать мгновенное состояние метрики, в случае отсутствия данных, метрика не должна ничего возвращать. Для этого должно выполняться условие, что retention_check_interval + retention <= scrape_interval — метрика считается истекшей после каждого сбора данных Prometheus.

В результате выполнения запроса генерирующего временные файлы в лог-файле PostgreSQL наблюдаем строки:
```
2020-04-21 02:51:15 AEST datname:,client:,app:,usename:,session:5e9dd2f3.1278 LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4728.0", size 46931968
2020-04-21 02:51:15 AEST datname:,client:,app:,usename:,session:5e9dd2f3.1279 LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4729.0", size 46276608
2020-04-21 02:51:15 AEST datname:postgres,client:[local],app:psql,usename:postgres,session:5e9dc0a8.112c LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4396.14", size 47194112
```
Экспортер, вернёт нам суммарное значение этих строк:
```
pg_grok_tpm_file_size_bytes{static="temp_file"} 1.40402688e+08
```
Повторим первый шаг и создадим временные файлы и выполним запрос к экспортеру через определенный ранее интервал.

Экспортер, вернёт нам суммарное значение для новых строк:
```
pg_grok_tpm_file_size_bytes{static="temp_file"} 1.1911168e+07
```
Таким образом мы имеет мгновенную величину: объем временных файлов созданных за время, прошедшее между получением метрик.

Теперь посмотрим, как поведет себя метрика при других условиях, установим достаточно большое времени жизни метрики (retention) и включенном накоплении (cumulative: true)
Повторим запрос из первого примера, в лог-файле PostgreSQL получим:

2020-04-21 03:03:40 AEST datname:,client:,app:,usename:,session:5e9dd5dc.12c6 LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4806.0", size 46260224
2020-04-21 03:03:40 AEST datname:,client:,app:,usename:,session:5e9dd5dc.12c5 LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4805.0", size 46833664
2020-04-21 03:03:40 AEST datname:postgres,client:[local],app:psql,usename:postgres,session:5e9dc0a8.112c LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4396.15", size 47316992

В выводе экспортера получим:

pg_grok_tpm_file_size_bytes{static="temp_file"} 1.40402688e+08

Выполним всё тоже самое, ещё раз. Получим:

2020-04-21 03:10:40 AEST datname:,client:,app:,usename:,session:5e9dd76e.1325 LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4901.0", size 46776320
2020-04-21 03:10:40 AEST datname:,client:,app:,usename:,session:5e9dd76e.1324 LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4900.0", size 45768704
2020-04-21 03:10:40 AEST datname:postgres,client:[local],app:psql,usename:postgres,session:5e9dc0a8.112c LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4396.18", size 47841280

И еще раз соберем метрики:

pg_grok_tpm_file_size_bytes{static="temp_file"} 2.80772608e+08

Таким образом мы имеет счетчик который может прирастать на произвольную величину, в том числе и отрицательную. Если между проверками не произошло изменение величины, будет возвращено последнее значение.

Рассмотрим последнюю ситуации с отключением накопления, установим значение cumulative в false и повторим все шаги, еще раз.

Результат первого запроса:

2020-04-21 03:41:04 AEST datname:,client:,app:,usename:,session:5e9ddea4.1393 LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp5011.0", size 11763712
2020-04-21 03:41:04 AEST datname:,client:,app:,usename:,session:5e9ddea4.1392 LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp5010.0", size 11501568
2020-04-21 03:41:04 AEST datname:postgres,client:[local],app:psql,usename:postgres,session:5e9dc0a8.112c LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp4396.19", size 11911168

Собираем метрики:

# HELP pg_grok_tpm_file_size_bytes Size of tmp file created by time
# TYPE pg_grok_tpm_file_size_bytes gauge
pg_grok_tpm_file_size_bytes{static="temp_file"} 1.1911168e+07

В итоге, из трех значений получили только последнее значение. Таким образом, при наличии нескольких значений с одинаковым набором меток будет выведена только последняя.

Резюме

Бесспорно grok_exporter является нужным инструментом для мониторинга приложений. Оно позволяет заглянуть в «трудно доступные», для систем мониторинга, места и обогатить мониторинг дополнительными (контрольными) метриками, оставаясь при этом достаточно простым, функциональным и легковесным.

При этом оно будет полезно и разработчикам, так как даёт, хотя бы и опосредованный доступ к журналам приложения, через систему мониторинга. Где можно коррелировать метрики от различных источников.

Еще одним позитивным моментом является то, что проект развивается и обрастает новым функционалом.

В свою очередь, надеюсь, что эта небольшая заметка будет полезна, в том числе и для самого проекта. Больше звёздочек, веселее работа!

Всем, спасибо!

Мониторинг ошибок и событий в журнале PostgreSQL (grok_exporter)