Всем привет! Меня зовут Димитрий, я 5 лет работал в «Хоум Банке» с SAS MA: начинал разработчиком SAS, закончил начальником отдела и техлидом SAFE-стрима. После объединения с «Совкомбанком» перешел в новую структуру.

Статья предназначена для технических специалистов: разработчиков и администраторов SAS CIS. Материал поможет понять проблематику ошибок падений маркетинговых кампаний, расскажет о механизме формирования корлога и том, как разделять его на отдельные логи по кампаниям. В приложении есть готовый проект с кодом для запуска парсера на своих логах.

В «Хоум Банке» мы использовали ПО компании SAS Institute. Для маркетинговых рассылок применяли ПО SAS Marketing Automation, MA SAS Intelligence Studio. SAS CIS позволял элементами графического программирования составлять маркетинговые кампании. Опытные пользователи могли использовать самописный код SAS/SQL.

Пример диаграммы CIS

Мы работали с ошибками, которые встречались в логах на уровне работы «ядра» CIS и писались в лог 6 веб-сервера Server6_1. Проблема заключалась в том, что лог один, а параллельно работающих процессов могут быть десятки, что очень неудобно.

Истоки проблемы

При разборе инцидентов на третьей линии поддержки мы использовали анализ логов. Часто у бизнес-пользователя возникала ошибка, а что конкретно «упало» и где искать «концы», было непонятно.

Про Customer Intelligence Studio. В SAS CIS есть разные типы узлов: стандартные и кастомные, с разработанным специалистами банка стандартизированным кодом или разово написанные пользователями. Есть и особые узлы коммуникаций. Обычно там происходит основная «магия» и интеграционные процессы с отправкой коммуникаций и фиксацией данных в таблице истории контактов.

Простые узлы: разделение подборки клиентов/договоров для A/B тестирования или выборка по фильтру логируются в корлог. Пользовательские, кастомные и узлы коммуникаций фиксируются в корлоге до момента сбора входной таблицы SQL, а результат работы кода выкладывается отдельным логом. Это было сделано давно и сильно упрощало разбор ошибок. Если «на пальцах»: на вход коммуникации передается список клиентов — таблица с 1 полем — уникальным идентификатором клиента. Проверки и интеграции кода коммуникации перед запуском основного кода собирают дополнительные данные, например: ФИО, адрес, телефон, доступный лимит по кредиту. После сбора этой автоматической таблицы, она передается на вход кода коммуникации — происходит отделение лога в файл. Доработки обычно были связаны именно с кодом коммуникации, поэтому и ошибки чаще всего находились там.

Мы улучшили возможность поиска нужного лога дополнительным выводом в него названия маркетинговой кампании, узла и некоторых суррогатных ключей. Лог искали через find в bash.

До этого приходилось узнавать суррогатные ключи через таблицы и джойны по имени кампании/узла, искать лог по этим ключам. Впоследствии мы добавили опцию отправки на почту информации о падении с логом, где могла быть ошибка. У пользователя появлялся код ошибки и лог, что сократило обращения в ИТ-команду на 90%.

Раньше, до оптимизации процессов, пользователь видел на экране сообщение: «Ошибка 1002, обратитесь к администратору» — и писал на почту поддержки. По переданному нам имени кампании, узла и времени ошибки, мы брали известные величины, отбирали таблицы с джойнами, получали код кампании и узла через имена пользователей и времени запуска. Идентификаторы обновлялись каждый запуск. После по этим кодам мы делали find в папке логов, обнаруживая нужный. Теперь лог можно было сразу найти по имени узла и примерному времени запуска на почте.

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

Пример лога, где «пишут» параллельно две кампании. Во вторых квадратных скобках указана сессия – и она разная.

Все они пишут параллельно в один файл. Как понимаете, поиск информации в таком файле затруднителен. Похоже на поиск иголки в стоге сена.

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

Учитывая объемы корлога — около 2 Гб текста за сутки — найти нужный кусок лога было сложно. Анализ мог длиться несколько рабочих дней.

Поиск решения

В процессе решения одной из проблем с SAS Institute, коллеги прислали приложение для анализа корлога. Но ресурсов ПК часто не хватало для работы этого приложения. Мы смогли извлечь профит: узнали принципы работы корлога и поняли, как его парсить.

Написание своего парсера

Главное, что я понял – в корлог идут записи, привязанные к ID сессии, который пишется в части строк. Я принял допущение, что все написанное под одним ID до появления другого ID относится к этой сессии. Позже эта версия подтвердилась.

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

Установили, что сессия – это одно подключение к SAS CIS. То есть, если кампания работает по расписанию, то на нее будет один набор сессий: сессия и дочерние. А вот если нужно разобрать ошибку пользователя, который запускал разные кампании, то сессия этих кампаний тоже будет одна, а значит, искать будет сложнее. В итоге парсер был оформлен в проект SAS Enterprise Guide и написан на языке SAS.

Развитие идеи

Первая проблема случилась, когда мы столкнулись с тем, что лог обрезается в 00:00. Ошибка была связана с кампанией, которая не отработала до полуночи. Часть лога перенеслась в следующий файл на запись. А парсер работает с конкретным логом, а не двумя.

Написали скрипт, который после плановой перезагрузки серверов в 7:00 и конца записи в лог приклеивает его ко вчерашнему и обнуляет текущий. Так перестали теряться сессии, а логи стали жить не с 00:00 до 00.00, а с 7:00 до 7:00, когда работает сервер. Простой скрипт на bash:

# Append core log to yesterday file
/bin/cat /opt/sas/sasconfig/Lev1/Web/Logs/SASServer6_1/SASCustIntelCore6.6.log >> /opt/sas/sasconfig/Lev1/Web/Logs/SASServer6_1/SASCustIntelCore6.6.log.$(date -d "yesterday" '+%Y-%m-%d')
# Clean today log
echo '' > /opt/sas/sasconfig/Lev1/Web/Logs/SASServer6_1/SASCustIntelCore6.6.log

Дополнительно сделали скрипт, который копирует сегодняшний лог с сервера метаданных на сервер Compute каждые 15 минут. Ранее это приходилось делать вручную, что занимало более 30 минут на трансфер лога с сервера на локальную машину и на второй сервер. Это было необходимо, поскольку лог пишется на META/MID сервере, а исполняющий код находится на Compute.

Аналогично, после обрезки лога в 7 утра он копируется с одного сервера на другой под именем "yesterday" – это упрощает работу с ошибками «за вчера».

Парсер на расписании и метрики – общее состояние кампаний, поиск «длинных шагов»

Со временем мы решили не только парсить лог при наличии ошибок и жалоб со стороны бизнес-пользователей, но и на основании кода создавать дополнительную отчетность. Например, мы анализируем лог и уведомляем пользователей о том, что какой-то шаг работал дольше положенного времени. Взяли рубеж в 3 часа. В дальнейшем такие узлы были разобраны и оптимизированы. Шаги часто переписывали сами бизнес-пользователи. Они же в первую очередь были заинтересованы в скорости, так как некоторые маркетинговые кампании работали «каскадом», каждая минута была ценна для финального времени. Иногда оптимизацию кода отдавали на аутсорс вендору.

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

Разбор проекта и кода парсера

Общий вид проекта

Рассмотрим проект для ручного запуска и анализа логов.

Первый блок ParseCoreLog проекта парсера — общий «проход» по всему логу. Здесь важно понять, какая сессия к какой кампании относится.

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

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

Второй блок ParseLogSession – мы подаем на вход имя сессии и используем макропеременную первого шага с адресом лога. На выходе получаем:

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

Для анализа ошибок этого обычно достаточно. Если нет понимания по строке ошибки, то это станет ясно из вырезанного лога: ошибка и контекст происходящего.

Пример таблицы со ссылкой на логи:

Пример таблицы со списком узлов:

Третий блок StreamParse опциональный. Он делает проход по всем вложенным логам, собирает строки с информацией о времени выполнения — суммирует все шаги, записанные во внешние логи и ранжирует их по времени, показывая самые долгие. Это необходимо, чтобы оценить общее время во вложенных логах и по таймингу выполнения найти аномалии — слишком долгие шаги, нуждающиеся в оптимизации).

Пример таблицы с расчётом времени работы шагов:

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

Парсер на расписании

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

Сейчас после нарезки готового лога в 7 утра программа проходит по всему логу и смотрит шаги дольше 3 часов. Они уходят на анализ, если повторяются изо дня в день.

Ранее по итогам работы парсера велся общий подсчет обработанных строк БД , всех запросов, шагов и времени работы в секундах, а также их соотношение. Это относительная аналитическая метрика, по которой мы отслеживали здоровье системы, необходимость замены железа, очистки больших таблиц.

Поскольку общее количество строк обычно примерно одинаковое, а среднее время на обработку должно сохраняться на одном уровне – это можно принять за стартовые условия. Из этих величин рассчитывается параметр R – количество строк, обработанных за единицу времени. Чем больше строк мы обрабатываем в промежуточных таблицах за единицу времени, тем лучше.

Параметр R рассчитывается следующим образом: все время в секундах ÷ все строки × 100 000. Хорошим параметром считалось число 50-60.

Со временем можно наблюдать кумулятивный эффект:наполняются исторические таблицы – показатель R растет. На тот же объем строк затрачивается больше времени. На обрабатывание 100 строк при запросе в терабайтную табличку времени уходит больше. Был выбран эталонный цифровой параметр и задан как цель на год — это мотивировало команду разработки и поддержки следить за ситуацией.

Также по метрике R можно было понять, насколько эффективны оказались какие‑то меры: очистки ключевых таблиц. Например, таблица истории контактов, или переезд на новые серверы.

В графическом отчете видно, что 16 июня произошел сбой, а 1 сентября была плановая остановка серверов и очистка таблицы.

Зеленая кривая — количество уникальных маркетинговых кампаний, запущенных за день. Красная кривая — количество кампаний, упавших с ошибкой. Синяя кривая — их отношение к падениям.

Выводы за несколько лет использования парсера

Во-первых, мы оптимизировали и автоматизировали разбор ошибок, которые возникают в результате работы маркетинговых кампаний. Часть ошибок автоматически обрабатываются, «достаются» из лога и отправляются бизнес-пользователю. Часто они типовые и кампейнер сам знает, что делать, имея на руках такой инструмент.

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

Иногда нужно покопаться и понять, в чем первопричина ошибки. Например, таблица не создалась, потому что закончилось место на диске. Или не было исходной таблицы, но не хватило сессий к БД. В любом случае у разработчиков на руках есть лог, имена кампании и узла. При необходимости корлог парсится, извлекаются все логи на системе, связанные с ошибкой. Если это сделано в течение суток-двух с момента ошибки, то все проблемы разбираются и делаются выводы. Растет стабильность и предсказуемость системы, проблемы решаются комплексно.

SLA отработки ошибок в среднем снизился с 2-3 дней до нескольких часов. Благодаря парсеру удалось отследить и оптимизировать все долгие узлы и процессы, что благотворно повлияло на общее время выполнения всех кампаний, разработчики стали лучше понимать логику «ядра» кампаний. Парсер корлогов можно скачать с репозитория.

Спасибо за внимание! Делитесь в комментариях своим опытом работы с корлогом и разбором ошибок SAS CIS. Если есть вопросы — задавайте, обсудим.

P.S. Если интересно узнать о карьере в Совкомбанк Технологиях — смотрите вакансии и направления работы.

Полный парсер Core Log SAS Customer Intelligence Studio и инцидент-менеджмент