Привет, Хабр.

В одном из проектов, связанных с мониторингом, мы используем Clickhouse, Prometheus, VictoriaMetrics, Grafana, Alertmanager и Vector.dev. Кстати, что общего у всех этих компонентов? Они написаны не на Java – это было одним из требований проекта, но речь ниже пойдет не об этом, а о Vector.dev.

Хорошая статья про Vector.dev есть на Хабре – но мы решили проверить свою карму, затащив Vector.dev в PoC. На текущий момент полет вполне нормальный: используем ограниченное количество source и sink’ов: File, Clickhouse, HTTP, JournalD и, конечно, сам Vector и его логи (немного погоняли kubernetes_logs, кстати, интересный доклад по теме логов Kubernetes был на недавней VK Kubernetes Conf’23).

Как оно там, внутри

На данный момент у нас двухуровневая иерархия векторов:

• агентский Vector.dev, который собирает логи с FreeIPA и OpenNebula серверов, а также наших Prometheus экспортеров;

• центральный Vector.dev, который агрегирует данные от агентских векторов.

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

Центральный Vector.dev запущен в Kubernetes и отправляет данные в кластер ClickHouse, агентские ставятся просто из deb-пакетов.

File source или работа с файлами

Ниже опишу некоторые конфигурации вектора с примерами обрабатываемых файлов – информация не сакральная, так как, почитав документацию, можно к таким же настройкам и прийти – но, надеюсь, с примерами лог-файлов будет для кого-то более наглядно.

Многострочные логи

У File source есть такая конфигурация как multiline. Из названия понятно, что объединяет несколько строчек логов в одну запись. Интересно то, что даже если на первый взгляд кажется, что в логах нет многострочных записей, то это может быть заблуждение.

Вот пример вывода части файла, ничего не указывает на многострочные логи:

root@ipatest:/var/log/ipa# tail -20 ipa-backup.log
Starting httpd Service
Starting ipa-custodia Service
Starting pki-tomcatd Service
Starting ipa-otpd Service
Starting ipa-dnskeysyncd Service

2023-07-04T06:22:07Z DEBUG stderr=ipa: INFO: The ipactl command was successful

2023-07-04T06:22:07Z DEBUG Starting external process
2023-07-04T06:22:07Z DEBUG args=['/bin/gzip', '/tmp/tmpmn9v4iqsipa/ipa/files.tar']
2023-07-04T06:22:07Z DEBUG Process finished, return code=0
2023-07-04T06:22:07Z DEBUG stdout=
2023-07-04T06:22:07Z DEBUG stderr=
2023-07-04T06:22:07Z DEBUG Starting external process
2023-07-04T06:22:07Z DEBUG args=['tar', '--xattrs', '--selinux', '-czf', '/var/lib/ipa/backup/ipa-full-2023-07-04-09-22-07/ipa-full.tar', '.']
2023-07-04T06:22:08Z DEBUG Process finished, return code=0
2023-07-04T06:22:08Z DEBUG stdout=
2023-07-04T06:22:08Z DEBUG stderr=
2023-07-04T06:22:08Z INFO Backed up to /var/lib/ipa/backup/ipa-full-2023-07-04-09-22-07
2023-07-04T06:22:08Z INFO The ipa-backup command was successful

Но если покопаться в файле, то замечаем, что запись лога является многострочной. Если это не обрабатывать отдельно, то каждая новая строчка такой многострочной записи будет новой записью в ClickHouse и никак не связана с предыдущей строкой лога.

2023-07-04T06:21:38Z DEBUG args=['tar', '--exclude=/var/lib/ipa/backup', '--xattrs', '--selinux', '-cf', '/tmp/tmpmn9v4iqsipa/ipa/files.tar', '/usr/share/ipa/html', '/etc/pki/pki-tomcat', '/etc/dogtag/', '/var/lib/pki', '/var/lib/ipa/sysrestore', '/var/lib/ipa-client/sysrestore', '/var/lib/ipa/dnssec', '/var/lib/sss/pubconf/krb5.include.d/', '/var/lib/certmonger', '/var/lib/ipa', '/run/dirsrv', '/run/lock/dirsrv', '/etc/dirsrv/slapd-DOMAIN-DCS-LAN', '/var/lib/dirsrv/slapd-DOMAIN-DCS-LAN', '/etc/bind/named.conf', '/etc/bind/ipa-ext.conf', '/etc/bind/ipa-options-ext.conf', '/etc/bind/named.keytab', '/etc/resolv.conf', '/etc/default/pki-tomcat', '/etc/default/krb5-kdc', '/etc/default/ipa-dnskeysyncd', '/etc/default/ipa-ods-exporter', '/etc/default/bind9', '/etc/ipa/nssdb/pwdfile.txt', '/usr/local/share/ca-certificates/ipa.p11-kit', '/etc/nsswitch.conf', '/etc/krb5.keytab', '/etc/sssd/sssd.conf', '/etc/ldap/ldap.conf', '/etc/security/limits.conf', '/var/lib/ipa/gssproxy/http.keytab', '/etc/ipa/kdcproxy/ipa-kdc-proxy.conf', '/etc/apache2/conf-enabled/ipa-pki-proxy.conf', '/etc/apache2/conf-available/ipa-rewrite.conf', '/etc/apache2/mods-available/ssl.conf', '/etc/apache2/sites-available/default-ssl.conf', '/var/lib/ipa/certs/httpd.crt', '/var/lib/ipa/private/httpd.key', '/etc/apache2/conf-enabled/ipa.conf', '/etc/ssh/sshd_config', '/etc/ssh/ssh_config', '/etc/krb5.conf', '/var/lib/ipa-client/pki/kdc-ca-bundle.pem', '/var/lib/ipa-client/pki/ca-bundle.pem', '/etc/ipa/ca.crt', '/etc/ipa/default.conf', '/etc/dirsrv/ds.keytab', '/etc/chrony/chrony.conf', '/root/ca-agent.p12', '/var/lib/ipa/ra-agent.pem', '/var/lib/ipa/ra-agent.key', '/root/cacert.p12', '/root/kracert.p12', '/etc/krb5kdc/kdc.conf', '/var/lib/ipa/certs/kdc.crt', '/var/lib/ipa/certs/kdc.key', '/var/lib/ipa/certs/cacert.pem', '/etc/systemd/system/multi-user.target.wants/ipa.service', '/etc/systemd/system/apache2.service.d/ipa.conf', '/etc/systemd/system/multi-user.target.wants/sssd.service', '/etc/systemd/system/multi-user.target.wants/certmonger.service', '/etc/systemd/system/pki-tomcatd.target.wants/pki-tomcatd@pki-tomcat.service', '/etc/opendnssec/conf.xml', '/etc/opendnssec/kasp.xml', '/etc/opendnssec/zonelist.xml', '/etc/ipa/dnssec/softhsm2.conf', '/etc/ipa/dnssec/softhsm_pin_so', '/etc/ipa/dnssec/ipa-dnskeysyncd.keytab', '/etc/ipa/custodia/server.keys', '/etc/ipa/custodia/custodia.conf', '/etc/gssproxy/10-ipa.conf', '/etc/hosts', '/etc/systemd/system/pki-tomcatd@pki-tomcat.service.d/ipa.conf', '/etc/ipa/nssdb/cert9.db', '/etc/ipa/nssdb/key4.db', '/etc/ipa/nssdb/pkcs11.txt', '/etc/tmpfiles.d/dirsrv-DOMAIN-DCS-LAN.conf', '/etc/systemd/system/dirsrv@DOMAIN-DCS-LAN.service.d/ipa-env.conf', '/var/lib/ipa/passwds/ipatest.domain.dcs.lan-443-RSA']

Поэтому для обеспечения логической связности сообщения логов некоторые записи приходится обрабатывать как многострочные. Но с вектором это достаточно просто, мы использовали следующую конфигурацию на основе регулярных выражений (здесь нам помогает то, что каждая отдельно взятая запись начинается с временной метки):

[sources.logs_freeipa_backup]
type = "file"
include = [ "/var/log/ipa/*backup.log" ]
multiline.start_pattern = "^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}Z"
multiline.condition_pattern = "^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}Z"
multiline.mode = "halt_before"
multiline.timeout_ms = 1000

Вектор уже сам склеивает многострочные сообщения и отправляет их в ClickHouse объединенными.

Fingerprint

Другой пример – это настройка правила определения «уникальности» лог-файла. Параметр fingerprint определяет, как файл идентифицируется. Это актуально для систем с включенной ротацией логов.

По умолчанию – это checksum (берутся строчки с начала файла и по ним считается контрольная сумма, даже интереснее по умолчанию берется одна первая строка). С одной стороны, какие могут быть проблемы? Действительно, большинство логов содержат в каждой записи уникальное значение – временную метку. Тогда все просто. Оказывается, что есть системы и лог-файлы, у которых шапка в начале каждого лог-файла одинаковая. В итоге получаем, что вектор не может различить файлы.

К сожалению, настройки, позволяющие игнорировать какое-то количество строк при вычислении контрольной суммы в векторе, нет (т.е., по сути, игнорировать статический заголовок), есть настройка (fingerprint.ignored_header_bytes), позволяющая пропускать определенное количество байт, но по выводы ниже видно, что рассчитать в нашем случае количество байт не получится. Но есть другая настройка – она определяет, какое количество строк учитывается для подсчета контрольной суммы. Ей мы и воспользовались.

root@ipatest:/var/log/dirsrv/slapd-DOMAIN-DCS-LAN# head -10 access
        389-Directory/1.4.3.6 B2022.332.1108
        ipatest.domain.dcs.lan:636 (/etc/dirsrv/slapd-DOMAIN-DCS-LAN)

[03/Oct/2023:14:30:50.945787186 +0300] conn=45 op=24857 SRCH base="ou=sessions,ou=Security Domain,o=ipaca" scope=2 filter="(objectClass=securityDomainSessionEntry)" attrs="cn"
[03/Oct/2023:14:30:50.946824663 +0300] conn=45 op=24857 RESULT err=0 tag=101 nentries=0 etime=0.001495205
[03/Oct/2023:14:31:35.998247986 +0300] conn=1561621 fd=132 slot=132 connection from local to /var/run/slapd-DOMAIN-DCS-LAN.socket
[03/Oct/2023:14:31:35.999675738 +0300] conn=1561621 AUTOBIND dn="cn=Directory Manager"
[03/Oct/2023:14:31:35.999694789 +0300] conn=1561621 op=0 BIND dn="cn=Directory Manager" method=sasl version=3 mech=EXTERNAL
[03/Oct/2023:14:31:35.999839429 +0300] conn=1561621 op=0 RESULT err=0 tag=97 nentries=0 etime=0.001454494 dn="cn=Directory Manager"
[03/Oct/2023:14:31:36.096347939 +0300] conn=1561621 op=1 SRCH base="cn=computers,cn=accounts,dc=domain,dc=dcs,dc=lan" scope=2 filter="(memberOf=cn=adtrust agents,cn=sysaccounts,cn=etc,dc=domain,dc=dcs,dc=lan)" attrs="* aci"

[sources.logs_freeipa_access]
type = "file"
include = [ "/var/log/dirsrv/*/access" ]
fingerprint.strategy = "checksum"
fingerprint.lines = 4
fingerprint.ignored_header_bytes = 0

Здесь установили, что «уникальность» файла логов отслеживается по первым 4 строкам (fingerprint.lines).

С чем столкнулись

Лимит на открытые файлы

Одна из задач была связана с мониторингом OpenNebula, включая логи виртуальных машин в ней. У OpenNebula может быть несколько нод, виртуальные машины между ними могут перемещаться и так далее. Машин в кластере может быть много, даже не единовременно, а вообще за всю историю существования кластера. Лог-файл обычно называется как <id_vm>.log. Для мониторинга мы указывали все файлы в каталоге с расширением log (/var/log/libvirt/qemu/*.log). Нам иногда не хватило файловых дескрипторов – мы получили ошибку “Too many open files (os error 24)”. Начали разбираться с выводов утилиты ulimit.

# ulimit -Sa
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 4122747
max locked memory       (kbytes, -l) 65536
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 4122747
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

# ulimit -Ha
core file size          (blocks, -c) unlimited
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 4122747
max locked memory       (kbytes, -l) 65536
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1048576
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) unlimited
cpu time               (seconds, -t) unlimited
max user processes              (-u) 4122747
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

Нас интересовал параметр open files (-n) 1024. Проблему временно решили, указав сервису вектора увеличенные значения LimitNOFILE/LimitNOFILESoft:

[Unit]
Description=Vector
Documentation=https://vector.dev
After=network-online.target
Requires=network-online.target

[Service]
…
StandardOutput=file:/var/log/monitoring/vector.log
ExecStartPre=/usr/bin/vector validate
ExecStart=/usr/bin/vector
ExecReload=/usr/bin/vector validate
ExecReload=/bin/kill -HUP $MAINPID
Restart=always
AmbientCapabilities=CAP_NET_BIND_SERVICE
EnvironmentFile=-/etc/default/vector
LimitNOFILE=2048
LimitNOFILESoft=2048

Параметр ignore_older

Решая проблему выше (и не только ее), хотели добиться, чтобы Vector.dev прекращал отслеживать логи в файлах, которые не менялись какое-то время (например, 30 дней). На самом деле, конкретно с проблемой для логов виртуальных машин нам бы это не помогло, т.к. виртуальна машина может быть остановлена на какое-то время, а потом снова включена (если это демо стенд), тогда ее «новые» логи уже потерялись бы (хотя для продуктивных нагрузок параметр в 30 дней вполне бы мог и работать).

К сожалению, такой настройки не нашли. Нашли параметр ignore_older. Сначала показалось, что это то, что требуется, но нет, это про другое. Документацию разработчики Vector.dev поправили.

TOML vs YAML

Изначально мы писали конфиги Vector.dev в toml, но потом yaml был выбран командой Vector.dev как формат по умолчанию с версии 0.33.0. Мы решили не терять времени, и наш инженер оперативно переписал конфигурацию агрегирующего Vector.dev из toml в yaml. С конфигурацией клиентских векторов решили действовать постепенно. Предлагаемая командой Vector.dev утилита vector convert-config справляется вполне хорошо, поэтому для нас изменение формата не стала большой проблемой (хотя лично мне для описания правил преобразования toml нравился больше).

Алертинг с помощью Vector.dev (интеграция с Alertmanager)

Неожиданно мы нашли еще одно интересное применение для Vector.dev – пока только в целях исследования. Требовалось опробовать функциональность  оповещения на основе встречающихся паттернов в логах, принимаемых вектором. На помощь нам пришел HTTP source. Паттерны выделяли с помощью регулярных выражений, далее таким образом отфильтрованные записи направляли в HTTP Source, который отправлял запрос к Alert Manager’у. Таким образом реализовали как создание алерта, так и его закрытие. Ниже приведен пример конфигурации, наши реальные обработки учитывают больше условий и в целом сложнее устроены.

event_syslog_error:
    type: remap
    inputs: 
    - filter_syslog_errors
    source: |
      . |= parse_regex!(string!(.message), r'systemd.+?: Failed to start (?P<iname>.+)\.$')
      .alertname = "Service " + .iname + " failure"
      .severity = "critical"
  filter_recover_syslog_error:
    type: filter
    inputs: 
    - vector
    condition: 
      type: vrl
      source: |
        match_any(string!(.message), [
                  r'systemd.+?: Started (?P<iname>.+)\.$'
                  ])
  recover_syslog_error:
    type: remap
    inputs: 
    - filter_recover_syslog_error
    source: |
      . |= parse_regex!(string!(.message), r'systemd.+?: Started (?P<iname>.+)\.$')
      .alertname = "Service " + .iname + " failure"
      .severity = "critical"

Полет нормальный

Пока считаем, что полет нормальный, и сегодня мы продолжаем использовать Vector.dev. Немного не хватает каких-то source\sink, наличия для самого Vector.dev дашборда в Grafana (это пережили), возможности написания расширений и пользовательских функций (все-таки VRL - это не Python, как минимум в функциональности).

Надеюсь, что статья для кого-то будет полезной, сообщество Vector.dev будет расти, а значит будет появляться новая функциональность, отправляться pull request’ы. Мы же в ближайшем времени планируем подключить Vector.dev к мониторингу логов Kubernetes кластеров.