Цикл наших статей по идеальному месту администратора продолжается. Сначала давайте вспомним, про что мы писали до этого:

• Изначальная идея: Идеальное место администратора DIRECTUM
• #0: Идеальное рабочее место администратора системы DIRECTUM #0. Вводная часть.
• #1: Идеальное рабочее место администратора системы DIRECTUM #1. Скриншоты.
• #2: Идеальное рабочее место администратора системы DIRECTUM #2. Запись экрана.
• #3: Идеальное рабочее место администратора системы DIRECTUM #3. Лог-файлы в DIRECTUM.
• #4: Идеальное рабочее место администратора системы DIRECTUM #4. Инструменты для анализа логов

В предыдущей статье мы познакомились с утилитами, с помощью которых можно анализировать логи. В данной статье мы разберём несколько примеров с анализом логов системы DIRECTUM.

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

В предыдущей статье мы выделили 9 шагов в пункте «Порядок анализа»:

1. Находим лог-файл.
2. Если лог-файл большой – открываем его в TotalCommander и находим нужный участок, который затем копируем и открываем в Notepad++. Если лог-файл меньше 100 мб – сразу открываем в Notepad++.
3. Применяем удобный синтаксис (например, Ada).
4. Включаем режим без переноса строк и находим нужный временной период.
5. Отмечаем точками останова начало и конец временного периода. Чтобы установить точку останова, нужно нажать мышкой рядом с номером строки, и строка отметится;
6. Переключаемся в режим с переносом строк, начинаем читать лог, находим ошибку.
7. Делаем поиск всех вхождений этой ошибки в лог и определяем периодичность её проявления.
8. Анализируем после каких действий в системе она возникает, устанавливаем причину появления ошибки.
9. Устраняем ошибку/находим обходные варианты решения.

В статье будет подробно рассмотрен 8 шаг анализа логов.

Структура записи в лог

Чтобы проанализировать лог-файл ошибки, необходимо знать его структуру. Поэтому сначала рассмотрим структуру записи в лог на примере утилиты SBLogViewer. Её мы рассматривали в предыдущей статье – это утилита от наших разработчиков, которая парсит лог-файл. Ссылки на скачивание есть в предыдущей статье.

Структура записи в лог в SBLogViewer

• Первые два столбца обозначают Дату и Время. В это время произошло какое-то исключение;
• ThreadID - номер потока внутри приложения;
• Далее идёт код системы и логин пользователя, у которого произошла ошибка в системе DIRECTUM;
• Информация – это дополнительная информация о процессе, которую программист хотел вывести в лог-файл для отображения. Часто бывает, что это поле остаётся пустым, либо в нём написано Debug (нет необходимости обращать внимания на данное слово, такие записи нужны для самих разработчиков);
• Исключение – обозначает класс исключения. В наших логах можно встретить тысячи разных классов исключений. В разных компаниях какие-то классы исключений могут встречаться чаще, а другие – реже. Поэтому с опытом анализа логов в своей организации приходит примерное понимание того, что могло произойти в системе, исходя из класса исключения – это очень полезный навык;
• Сообщение – это текст ошибки, который мог видеть пользователь при работе в системе, или который был записан в лог-файл в фоновом режиме;
• Модуль – это процесс, в котором произошла ошибка;
• Далее написана версия IS-Builder. Замечу, что обращаться к справке в ходе анализа ошибки необходимо к той версии системы, в которой произошла ошибка, так как в некоторых аспектах информация по версиям может сильно отличаться. И тут есть полезный лайфхак: начиная с версии DIRECTUM 5.4 второе число в версии IS-Builder обозначает версию DIRECTUM (например, в данном случае 7.56.0.1038 – значит, версия 5.6);
• Далее идёт ИД процесса (его можно посмотреть у любой запущенной утилиты в диспетчере задач).
• CompId - тип компоненты, в которой происходило действие;
• Локальный пользователь – пользователь в системе windows. Может отличаться от пользователя системы DIRECTUM, если стоит не windows-аутентификация;
• Показано? - обозначает визуальное отображение ошибки (если True, то пользователь увидел ошибку, иначе – нет). В случае, если написано True, у пользователя (если есть такая возможность) можно попросить сделать скриншот ошибки или запись экрана с её воспроизведением (ранее мы уже разбирали как сделать скриншоты и как сделать запись экрана);
• Стек вызовов – это запись последовательности вызываемых процессов, после которых возникло исключение.

Анализ записи в лог

Открываем лог в Notepad ++ и применяем к нему стандартный синтаксис Ada (Синтаксисы -> A -> Ada). Делаем перенос по строкам, чтобы строки умещались в экран (Вид -> Перенос строк) и получаем примерно то, что представлено на скрине ниже.

Смотрим на нижнюю строчку и видим, что всё происходило в процессе SBRte.exe в компоненте REPORTS#ctReference (написано снизу). Это значит, что ошибка возникла при работе пользователя в компоненте "Разработка отчётов". Пользователь ошибку видел. Класс исключения (сверху) – EInvalidOp. Какая-то операция выполнилась неправильно (Invalid Operation).

Анализ стека ошибки

Теперь, узнав полезную информацию об ошибке, можно проанализировать её стек, чтобы попытаться воспроизвести действия пользователя. Правильно начинать анализировать стек вызовов снизу-вверх, потому что он имеет структуру дерева: чем выше по нему поднимаемся – тем меньше происходящие события, чем ниже – тем крупнее. Процессы, записанные внизу стека имеют в себе много составляющих - поэтому они считаются крупными. Чем выше мы поднимаемся по стеку, тем лучше понимаем, из-за какого конкретного процесса произошла запись в лог. Для чтения логов не обязательно разбираться в структуре ООП: что такое модули, классы, пространства имён, сборки, методы и т.д. Достаточно просто разбираться в английском языке, т.к. названия событий обычно говорят сами за себя. Ремарка: если запись начинается с нескольких заглавных букв, то, вероятно, это действие происходит в нашей платформе IS-Builder, именно их и стоит анализировать в логах. Анализируем:

Нижняя часть стека ошибки

В нижней части не найдутся конкретные процессы, в которых происходили ошибки, но можно примерно понять, в какой части системы они были. В данном случае всё начинается с записейи Forms, которая несёт смысл визуальных форм, далее исобытия переходят в Controls – понимаем, что это контроли на визуальных формах (может быть, кнопки на ленте или записи в списке – это не так важно), видим запись DblClick – пользователь дважды нажал мышкой по какому-то из контролей.

Системные операции

После предыдущих действий запустились системные операции (System) – их мы пропускаем, т.к. системные ошибки вряд ли встретятся в наших логах. Можно дважды кликнуть по надписи System, и Notepad ++ подсветит данное слово во всём лог-файле – тогда будет визуально понятно, до какого момента можно не смотреть запись лога (или же можно с комбинацией Ctrl+F выделить слово и найти его во всем документе - удобно, если лог не помещается в экран).

Сообщение об ошибке

После системных процессов встречается ошибка действия «RunAction» в справочнике – это действие содержит некий код, в третьей строке которого вызывается сам отчёт. А выше в логе, почти сразу встречается другая ошибка уже внутри отчета, в строке 539. Она же встречается в самом конце лога (то есть вверху).

После первого повторения конечной ошибки очень много действий связано с SBInter (на рисунке подсвечено слово SBInter, и Notepad ++ сам его подсветил) – это интерпретатор кода ISBL. Понимаем, что запускаются и проводятся какие-то вычисления на ISBL. Доходим до верха и теперь становится понятно, что после вычислений в отчёте "MBAnAccRpt@PUMAnnualPurchaseFromSME" (подсвечено серым цветом на рисунке) возникла ошибка (Invalid floating point operation), связанная с операцией с плавающей точкой.

Воспроизведение действий

Можно восстановить события: пользователь кликнул по кнопке (RunAction) в справочнике «Отчёты», чтобы сформировать отчёт (MBAnAccRpt@PUMAnnualPurchaseFromSME). Запустился расчет отчёта, начали выполняться вычисления, которые привели к ошибке в операции с плавающей точкой в 539 строке. Администратору понятно, что пользователь всё делал правильно. Следующим шагом будет открыть этот отчёт, найти в нём строку с ошибкой, разобраться, какие вычисления происходят в ней и какая может быть ошибка в операции с числами.

Итоги

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

По традиции ждём ваших комментариев с best practice по анализу логов.