Grok-паттерны для логов 1С: день на отладку, зато теперь видно что происходит

После того как мы развернули ELK в продакшне для нескольких клиентов, с nginx и PostgreSQL всё стало более-менее понятно: есть готовые grok-паттерны, документация, примеры на Stack Overflow. Но один клиент пришёл с требованием разобрать ещё и логи 1С Предприятия 8.3 - технологический журнал платформы. И вот тут начались приключения.

Что такое технологический журнал 1С

1С Предприятие умеет писать свой собственный лог событий - называется технологический журнал. Включается через файл logcfg.xml, пишет в папку с подпапками по часам вида YYMMddHH/, один файл за каждый час работы. Формат строк - что-то своё, не syslog, не JSON, ничего стандартного.

Строчка из реального лога выглядит примерно так:

10:23:45.123456-0,SDBL,3,process=rphost,p:processName=КлиентскоеПриложение,OSThread=4567,t:clientID=12,Calls=1,Rows=845,RowsTotal=845,Duration=1234567

Время - в начале, с микросекундами. Тип события - SDBL (это база данных), EXCP (исключение), CALL (вызов), CONN (соединение) и так далее. Потом набор ключ=значение через запятую, но порядок полей непостоянный и зависит от типа события.

Стандартного grok-паттерна для этого нет. Значит, пишем сами.

Подход: сначала Grok Debugger, потом конфиг

Ковырять grok прямо в конфиге Logstash - это путь страданий. Каждая итерация: правишь конфиг, перезапускаешь Logstash, смотришь в Kibana или в лог самого Logstash, читаешь ошибку, идёшь в конфиг снова. Цикл занимает по несколько минут, это мучительно.

Нашли онлайн-инструмент - Grok Debugger. Вставляешь сырую строку, пишешь паттерн, сразу видишь что вытащилось и что нет. Итерации - секунды. Весь день работали там, в Logstash конфиг перенесли только когда паттерн уже стабильно работал.

Первый рабочий паттерн для общей строки:

%{POSINT:ts_hour}:%{POSINT:ts_min}:%{POSINT:ts_sec}\.%{POSINT:ts_usec}-%{POSINT:duration_us},%{WORD:event_type},%{POSINT:event_level},%{GREEDYDATA:fields_raw}

Это вытаскивает время, тип события, уровень и хвост строки как сырой текст. Хвост потом разбирается отдельным фильтром через kv - key-value плагин Logstash, который умеет распутывать key=value,key=value структуры.

Потом добавили специфичные паттерны для отдельных типов событий. EXCP - исключения - особенно важны:

%{POSINT:ts_hour}:%{POSINT:ts_min}:%{POSINT:ts_sec}\.%{POSINT:ts_usec}-%{POSINT:duration_us},EXCP,%{POSINT:event_level},process=%{DATA:process_name},OSThread=%{POSINT:os_thread},%{GREEDYDATA:exception_text}

Для EXCP текст ошибки идёт в конце и может содержать запятые внутри - поэтому GREEDYDATA и он должен стоять последним.

Конфиг Logstash

Структура конфига получилась такая: отдельный input читает файлы технологического журнала через file-плагин, filter применяет grok и kv, output шлёт в Elasticsearch.

Несколько мест где споткнулись:

Файловый input и подпапки. Logstash file-плагин не рекурсивен по умолчанию. Технологический журнал пишет в подпапки YYMMddHH/, значит надо указывать glob-паттерн path => "/var/log/1cv83/journal/**/*.log". Двойная звёздочка работает - проверили.

Кодировка. 1С на Windows пишет логи в CP1251. Если сервер приложений 1С под Windows, файлы приедут в 1251, Logstash по умолчанию ждёт UTF-8 - получаем кракозябры. Параметр codec => plain { charset => "CP1251" } в input спасает.

Временна`я метка. Время в логе 1С - без даты, только время. Дату берём из пути к файлу. В Logstash это решается через mutate + date фильтры: сначала вытащить дату из пути регуляркой, потом склеить с временем из строки и скормить date-фильтру для установки @timestamp.

kv-фильтр и экранирование. Поля вида p:processName=КлиентскоеПриложение - с префиксом p: - kv вытаскивает как p:processName. Kibana воспринимает двоеточие в имени поля нормально, но в запросах приходится экранировать. Лучше при парсинге переименовывать через mutate: убрать префикс p: и t: или заменить двоеточие на подчёркивание.

Что получилось

После настройки каждая строка технологического журнала превращается в структурированный документ в Elasticsearch. Теперь можно:

• Найти все исключения за последний час. Фильтр event_type: EXCP в Kibana, временна`я шкала.
• Найти медленные запросы к БД. Фильтр event_type: SDBL AND duration_us: [5000000 TO *] - все SDBL-события дольше 5 секунд.
• Сопоставить исключение с конкретным клиентским сеансом. Поле t:clientID теперь есть в каждом событии, можно фильтровать по нему.

До этого разбор инцидентов в 1С выглядел так: открываешь папку с логами, ищешь нужный час, открываешь файл, grep по ключевому слову, пытаешься восстановить хронологию из разрозненных строк. При активной системе файл за час - несколько мегабайт.

Сейчас - открываешь Kibana, ставишь фильтр по типу события и времени. Всё.

Где остались вопросы

Клиент использует кластер серверов 1С - несколько процессов rphost на нескольких хостах. Агрегация логов со всех хостов работает, но корреляция между событиями на разных хостах по одной пользовательской сессии пока неудобна - идентификаторы сессий разные в разных частях кластера. Это, судя по документации 1С, особенность архитектуры платформы.

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

В рамках сопровождения инфраструктуры это вполне рабочая схема: один день на написание и отладку паттернов, потом логи 1С живут в ELK наравне с остальными компонентами стека.