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

Меня зовут Крапивин Андрей, некоторые меня знают по статьям на Инфостарте. Одна из самых популярных – это «Не только автоматизация учета», о том, как мы участвовали в соревновании, сражались с шарпистами и питонистами. Нам надо было написать ботов для космических кораблей и отправить их на сражение. Мы написали их на 1С. 

Вот пример нашего боя, мы тут синие. Очень скоро мы тут потеряем два корабля, потому что они просто куда-то улетят. Самое интересное, что в этом бою мы победим одним кораблем, а во всем соревновании у нас золотая медаль. 

Вопрос – как это отладить? А вот здесь начинается самое интересное. 

• Здесь нет пошагового выполнения – программа уже пошла;

• Нет никаких точек останова;

• Все, что у нас есть – это отладка через «Сообщить». Мы выводим какие-то данные и на основе их решаем, что же делать дальше. 

Как собрать информацию об ошибке в продакшен?

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

Для отладки надо получить удаленный доступ. Если его дадут – хорошо, но недостаточно. Надо еще найти человека, у которого есть пароль от конфигуратора и надеяться, что включена отладка сервера. 

Чтобы этого избежать и быстро решить проблему, нужно собрать максимальное количество информации, а именно:

• контекст ошибок;

• сами ошибки;

• и, желательно, действия пользователя. 

Об этом чуть подробнее.

Контекст. На самом деле, все просто. Это:

• платформа;

• конфигурация, ее версия (чтобы не тратить время, когда ты человека спрашиваешь: «Какая у вас версия конфигурации», а он отвечает: «8.3.13»)

• идентификатор клиента;

• идентификатор пользователя базы данных;

• любые настройки.

Дальше собираем ошибки. 

• самое простое – это просто забрать информацию об ошибке;

• постараться забрать цепочку исключений или стек вызовов;

• и знать место возникновения ошибки.

Действия пользователя – выполняемые человеком запросы, любые действия. Про них часто забывают. Их желательно тоже знать, чтобы потом человека не спрашивать: «Что же ты такое нажал?» Он скажет: «Ничего, оно само».

Сбор логов

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

В прошлом году был хороший доклад Кашафутдинова Тимура «Логирование в приложениях», в котором все технические детали, на самом деле, были разобраны. Если кратко, то:

• Логировать через «Сообщить» – плохая идея, потому что вряд ли пользователь обрадуется, когда ему на каждое действие будет выводиться «портянка» текста.

• Писать в файл – тоже не очень хорошая идея, особенно если у вас клиент-серверный контекст.

• Писать в регистр сведений может быть неудачно, потому что у вас могут быть блокировки (также не надо забывать про режим транзакций).

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

• Идеальный вариант – если у вас есть какой-то внешний веб-сервис, в который вы эти данные можете отправить. Нам повезло, у нас такой был.

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

Дальше по таймингу или по возникшему исключению контексты объединяются и отправляются в веб-сервис.

Примеры сбора логов

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

Вот таким образом мы собираем данные по работе с интерфейсом:

• нажатия любых кнопок;

• ввод в поля;

• флажки/переключатели;

• диалоги выбора файла и т.д.

На сервере это выглядит вот так. 

Мы используем структурный лог. Это такой лог, куда вы, например, отправляете сообщение:

«Не удалось провести {{ТипДокумента}} №{{Номер}} от {{Дата}}»

Ключевые данные – ТипДокумента, Номер и Дата уходят дополнительным сообщением, чтобы их потом не пришлось разбирать.

И самое интересное – как мы работаем с исключениями:

• мы в обязательном порядке их пишем в журнал регистрации, чтобы эти ошибки потом можно было хоть где-то достать;

• и стараемся собирать целиком стек вызова этого исключения. 

Подходы к логированию

Какие подходы мы используем при ведении логирования?

Желательно, чтобы логирование было с избытком. Пусть лучше там будет много информации, чем ее не хватит. Но нужно понимать, что эта система не бесплатна. Вызов функции логирования может достаточно сильно сказаться на производительности – она может упасть до 50%. 

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

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

• Дальше – можно использовать отладку через логирование. Это такой интересный подход, когда вы просто запускаете программу и смотрите, что у вас высыпалось в лог. Если вам какой-то информации не хватает, вы ее добавляете, и пытаетесь решать проблемы просто с изучением этой информации.

• И, конечно же, итерации. Вряд ли вы сразу сделаете идеально. Обязательно что-нибудь пойдет не так. Ничего страшного в этом нет.

Анализ логов

Данные мы собрали. Теперь займемся их анализом.

Clickhouse

Первая система, которую мы попытались использовать для анализа, это – Clickhouse (достаточно внезапно, наверное). Просто так получилось, что веб-сервис, который мы используем, умел сразу «из коробки» отправлять данные в Clickhouse. 

Clickhouse – это база данных специального формата. Вот так выглядит ее веб-интерфейс. 

Какие у Clickhouse плюсы и минусы?

Основные плюсы:

• Аналитика – Clickhouse создан для того, чтобы собирать аналитику: мы можем посчитать, сколько у нас клиентов, какие комбинации клавиш они использовали;

• SQL-подобные запросы – синтаксис там очень похож на SQL с небольшими доработками;

• Есть возможность связи таблиц – если у нас в эту же систему идут логи веб-сервиса, мы можем соединить две таблицы и узнать всю картину.

Из минусов:

• Скорость работы. Clickhouse очень неповоротливый, он любит обрабатывать большие данные – вы ему запрос отдали, он его покрутил, выдал в таблицу результат;

• У него отсутствуют уведомления, как таковые;

• Достаточно бедная система визуализации данных – это, в основном, таблица результата и еще две-три диаграммы.

Чтобы компенсировать минусы Clickhouse, его можно использовать совместно с сервисом Redash.

Вот так выглядит Redash:

• у него очень большой набор диаграмм;

• а также хороший сервис уведомлений – он интегрируется с Telegram, с почтой и со Slack.

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

Elasticsearch

Это, конечно, же, Elasticsearch.

Вот так у него выглядит веб-интерфейс Kibana. 

Какие у него получились плюсы и минусы?

Плюсы:

• популярность – это, наверное, самый популярный стек для того, чтобы работать с логами;

• найти по нему документацию, в том числе, русскоязычную, вообще не составляет никаких проблем – есть и статьи на Инфостарте;

• достаточно простой формат отправки данных.

Из минусов:

• по крайней мере, в той версии, которую мы пробовали, отсутствуют какие-то уведомления о событиях (в последних версиях, по-моему, в Kibana есть возможность интегрироваться со Slack и с Telegram);

• обязательно нужно знать, что вы хотите найти, потому что у вас, по сути, будет большая простыня текста, из которой вы какими-то уточняющими запросами будете черпать информацию. Я видел большие статьи на wiki на тему: «когда в сервисе возникла такая-то ошибка, вам нужно сделать такие-то запросы и анализировать эти данные».

• отсутствует настройка хоть каких-то прав доступа – у всех, у кого есть доступ в Kibana, есть доступ к вашим логам. Возможно, это плохо.

Graylog

Следующий движок, который мы попробовали – это Graylog. Он достаточно молодой, но набирающий популярность.

Вот такой у него интерфейс. 

Какие у него плюсы и минусы? 

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

• у него очень приятный интерфейс, и он сразу же собирает простенькую аналитику. 

• также у него есть возможность настроить права доступа.

Из минусов:

• повторные уведомления. Когда вы получаете любую ошибку, которая возникла у пользователя, это хорошо. Но при групповом перепроведении документов вы получите к себе в Telegram поток сообщений. Даже при том, что у Graylog есть возможность сказать, что вы хотите получать сообщения раз в полчаса, не больше – полчаса пройдет, и вы получите оставшуюся порцию сообщений. 

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

Все эти сервисы достаточно хорошие, мы бы, наверное, на этом и остались – аналитики сидели бы в Clickhouse, вертели бы данные, как хотят, а мы бы в Kibana анализировали, что у нас пошло не так. Но мы чуть-чуть поискали, и нашли сервис Sentry.

Sentry

Sentry – это, как раз «Часовой» (или «Страж»). Чем же он так отличается?

Во-первых, это трекер ошибок, сервис, который заточен именно на обработку ошибок. Вот такой у него веб-интерфейс.

У него огромная поддержка языков. 1С там, правда, нет, но – когда нас это останавливало?

И он OpenSource. Вы можете скачать его по ссылке https://github.com/getsentry/sentry и быстро себе поставить. Он написан на Python, соответственно, его можно доработать. 

Также его можно использовать на сайте https://sentry.io/ – можете там зарегистрироваться, чтобы его «потыкать». 

Как передать данные в Sentry?

Как все это работает?

• первым делом из всего многообразия логов вам нужно выделить только исключения;

• далее их нужно отправить в какую-нибудь систему, которая их преобразует в требуемый формат (у нас для этого используется 1С);

• и после этого отправляете их в Sentry.

Например, вот так. Это – пример обработки сообщения. Надо выделить:

• ошибку;

• пользователя, у которого она возникла;

• и контекст. 

После этого просто собираете JSON и отправляете его по HTTP.

Важные сущности – Event и Issue.
Уведомление об ошибке

Теперь возникают две важных сущности Sentry.

• Первая сущность – это Event (событие). То, что мы отправили в Sentry на предыдущем шаге, это будут, как раз, события. Они должны содержать в себе:

  • сообщения;

  • описание исключений;

  • или описание цепочки исключений. 

• Sentry анализирует эти три параметра и собирает из них задачу (Issue).

Дополнительно можно отправлять данные:

• о пользователе;

• платформе, которой он пользуется;

• добавлять теги;

• и любые дополнительные данные.

Вот так выглядит уведомление об ошибке, которое приходит к нам в Slack.

Самое важное, что вы получаете уведомление только о новых задачах – не событиях, а задачах. 

Дальше вы можете эти задачи либо разрешать, либо игнорировать. Например, если ошибка возникла один раз, и вы сейчас ничего с этим делать не хотите, вы просто ставите эту задачу на игнорирование, пока она не возникнет еще 10 раз (или у 10 пользователей).

Как анализировать ошибки с помощью Sentry?

Я думаю, проще разобрать на примере простенькой конфигурации. 

У пользователя возникла ошибка. Как эту ошибку можно анализировать с помощью Sentry? Самое простое – создать задачу, куда отправить текст этой ошибки. 

Задача в Sentry будет выглядеть вот так. 

В строке заголовка мы уже сразу видим дополнительную аналитику – сколько раз и у каких пользователей возникла эта ошибка.

Смотрим, что еще здесь есть:

• ниже выводится описание исключения, которое мы собрали из нашего сообщения об ошибке;

• справа мы видим два графика, как часто эта ошибка вообще появлялась:

  • за последний месяц;

  • и за последние 24 часа. 

Что еще можно вытянуть из сообщения об ошибке 1С?

Самое простое – это собрать в качестве данных о событии сведения о пользователе и о среде запуска.

Сведения о пользователе будут выглядеть вот так.

О среде запуска – вот так.

Эту же информацию можно также использовать в качестве тегов.

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

Те, у кого 8.3.15, могут для исключения вывести в «Информацию об ошибке» полный стек ее возникновения.

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

• вы вызываете исключение – обработали на верхнем уровне;

• потом дописываете информацию на всех следующих уровнях;

• и результат отправляете в Sentry.

И большой блок информации, которая нам поможет разобраться, в чем же дело – это действия пользователя перед ошибкой.

Работа с issues

Хорошо, данные мы отправили. Начинаем с ними работать. 

Задачу можно или разрешить, или проигнорировать:

• Если мы говорим, что ее разрешаем, тут есть дополнительные условия – мы говорим, что решаем ее прямо сейчас или в следующем релизе. Если мы отметим, что решим задачу в следующем релизе, то до этого релиза нам уведомления приходить не будут. Мы говорим: «В этом релизе мы задачу не решаем, решим ее в следующем», и все, нас сервис больше не уведомляет.

• Можно проигнорировать, если задача не массовая. Зачем решать проблему у одного пользователя? Пусть задача возникнет у 10 тысяч пользователей, тогда, может быть, будет интересно.

Почему Sentry?

Почему же все-таки стоит пользоваться Sentry? 

• Сервис Sentry, в отличие от всех остальных, дает фокусировку на ошибках. Никто не полезет в логи, пока не возникнет проблема (если вы не занимаетесь аналитикой). 

• Он позволяет вытянуть максимальный контекст в короткое сообщение. 

• И у него хорошая оптимизация хранения данных. То есть, он не хранит всю подряд информацию, если произошло повторное событие – он просто стыкует его в одно.

И почему еще следует пользоваться Sentry?

У них на главной странице сайта есть надпись: «Серьезно, перестаньте надеяться, что пользователи сообщат вам о своих ошибках».

Могу рассказать пример из практики. Был конец рабочего дня, часов 20. Мне в Slack приходит сообщение, что у пользователя ошибка. Конец рабочего дня – я ничего не стал делать, прихожу на следующий день – там у пользователя уже 15 попыток, но информации от него до сих пор нет. Мы нашли менеджера клиента, позвонили ему, он говорит: «У меня все хорошо». В итоге на службу поддержки клиент обратился только через неделю – к этому моменту у него было уже 150 попыток сделать действие.

Что нужно сделать?

Что нужно, чтобы начать этим пользоваться?

• Начинайте собирать логи:

  • возьмите библиотеку Logos;

  • пишите данные в журнал регистрации;

  • собирайте технологический журнал.

• Если вы хотите только искать данные, то можете пользоваться:

  • Elastic Search;

  • или Graylog.

• Если вам нужна аналитика, то тут вам, скорее всего, поможет:

  • Clickhouse;

  • или, например. Graphite.

• Если вы хотите аккуратно работать с ошибками, тогда подойдут сервисы:

  • Sentry;

  • Rollback;

  • а также у Google есть сервис для работы с ошибками.

Материалы

Я постарался собрать материалы, какие есть по логированию. Здесь есть и статьи с Инфостарта, и готовые библиотеки:

• Logos для 1C – https://github.com/silverbulleters/logos-1c

• ТЖ в Elastic – //infostart.ru/public/1073101/

• ЖР в Elastic – //infostart.ru/public/545895/

• ЖР в Clickhouse – //infostart.ru/public/951551/

• Graylog и 1С – //infostart.ru/public/1011440/

• Google Analytics – //infostart.ru/public/723481/

• Google Cloud Platform – //infostart.ru/public/796913/

А это – мои материалы:

• Наш веб-сервис «Метрика» – https://github.com/KrapivinAndrey/Metrika, можете на него посмотреть. Может быть, найдете вдохновение. 

• А также база, которая занимается тем, что подготавливает сообщения для Sentry – https://github.com/KrapivinAndrey/1C_Sentry.

Вопросы:

• Расскажи по поводу действий пользователя – они отображается в Sentry, но это же не часть контекста исключения. Каким образом они собираются, показываются?

• Эти данные у нас собираются во внешний веб-сервис. И есть специальная база 1С, которая следит за потоком именно ошибок в этом веб-сервисе. Причем, данные у нас разделены – в один поток мы пишем ошибки, а во второй поток – все действия пользователя. Как только эта база находит ошибку, она дополнительно подключается ко второму потоку и забирает из него последние 10 событий по ID пользователя. А потом передает эти данные в Sentry.

• А как получить стек вызовов для исключения?

• В платформе 8.3.15 в «Информации об ошибке» есть возможность посмотреть целиком стек ее возникновения. Это – места возникновения ошибки с указанием исходной строки кода. Это то же самое, как вы при отладке в конфигураторе ставите точку останова и там есть кнопка «Стек вызовов». Теперь тот же самый стек вызовов можно увидеть в информации об ошибке при возникновении исключения. Это в 8.3.15 «из коробки».

• Каждое действие пользователя записывается в 1С?

• Не в 1С, а в отдельный веб-сервис. 1С здесь, наверное, не потянет. Особенно, если писать в журнал регистрации. А если это сторонний веб-сервис, то почему бы и нет. Каждое действие пользователя (нажатие на кнопку, изменение поля ввода, диалог) складывается в специальные стеки, которые по таймауту отправляются в веб-сервис.

• Ты показывал куски кода, которым все это отправляется в Sentry – это закрытое решение или все это есть в той базе, которая выложена у тебя на GitHub?

• База интеграции с Sentry выложена на GitHub, можете ее скачать и посмотреть.

****************

Данная статья написана по итогам доклада (видео), прочитанного на конференции INFOSTART EVENT 2019.

Больше статей можно прочитать здесь.

*************