Протоколирование работы приложения
Введение
В 2003 году я работал с заказчиком, который находился на расстоянии нескольких
тысяч километров от меня. Сначала работа над проектом шла по накатанной схеме,
которая давала хорошие результаты в прошлом. Постепенно дело приближалось к
выпуску релиза. После того как заказчик просмотрел очередную промежуточную версию,
я получил от него отчет об ошибке: «Ваша программа у меня не работает». Как
всегда емко и понятно…. Не все заказчики владеют навыками тестирования.
Потом была длительная переписка, чтобы выяснить подробности. Затем мы обнаружили,
что ошибка не воспроизводится на нашем железе. Удаленного доступа к компьютеру
нет. Ехать ради этого на другой конец земного шара – глупо.
Именно тогда я серьезно задумался о механизме, который бы позволял избегать
таких ситуаций в дальнейшем.
Требования к системе
При разработке механизма идентификации проблем на стороне заказчика я ставил
перед собой следующие требования:
- Обнаружение причин краха программы.
- Сбор информации о среде выполнения. На первый взгляд это не очень важно,
т.к. хорошая программа сама должна проверять доступность всех компонентов.
С другой стороны, разные версии ОС или вспомогательных компонентов могут иметь
немного разное поведение. Поэтому при воспроизведении ошибки очень помогает
знание конфигурации на стороне пользователя.
- Сбор информации о действиях пользователя. Это необходимый шаг, т.к. пользователь
часто не может внятно описать, что же он делал с программой.
- Протоколирование работы не должно влиять на работу приложения.
Решение
Для обнаружения причин краха программы очень удобно использовать мини-дампы.
Об этом можно почитать в статье «Отладка
приложений на C++. Часть 5 (мини-дампы)». Дополнительная функциональность
неактивна до поры до времени и не видна пользователю. В случае же краха – вы
всегда сможете получить от клиента снимок памяти и состояния процессора для
анализа.
Для воплощения оставшихся требований замечательно подходит протоколирование
работы программы. Идея была взята из Linux – там есть замечательная API функция,
которая пишет сообщения в системный журнал.
Мы разработали свой улучшенный аналог для Windows. Функция имеет примерно такой
прототип:
void WriteLog(int iDebugLevel, int iLineNum, const char * strFileName, const char * strFuncName, const char *strDebugStr, ...);
Первый параметр указывает важность ошибки: критическая, информация, отладка
и т.п. Классификация сообщений ограничена только вашей фантазией и результатом,
который надо получить.
Второй, третий и четвертый параметры определяют место формирования сообщения.
Последние два параметра определяют содержимое отладочного сообщения. Их формат
полностью соответствует функции printf.
Для того, чтобы увеличить информативность сообщений, автоматизировать их создание
и уменьшить объем кода мы сделали несколько макросов.
#define LOG_BEGIN_FUNCTION(fname) const char *___debug__func__name = #fname;
#define WLOG_INFO(dbgstring) g_pLogFile->WriteLog(LOG_INFO, __LINE__, __FILE__, ___debug__func__name, dbgstring)
#define WLOG_WARN(dbgstring) g_pLogFile->WriteLog(LOG_WARN, __LINE__, __FILE__, ___debug__func__name, dbgstring)
#define WLOG_ERR(dbgstring) g_pLogFile->WriteLog(LOG_ERR, __LINE__, __FILE__, ___debug__func__name, dbgstring)
#define WLOG_FATAL_ERR(dbgstring) g_pLogFile->WriteLog(LOG_FATAL_ERR, __LINE__, __FILE__, ___debug__func__name, dbgstring)
К сообщениям программиста добавляется дополнительная информация: время, имя
функции, файл и номер строки. Это очень сильно помогает найти место, которое
сгенерировало сообщение. Все эти манипуляции делаются очень просто средствами
препроцессора.
Сбор информации о среде выполнения - это тема отдельной статьи. При старте
программы она может вывести все данные в лог, используя описанные макросы.
Модуль для записи протокола работы представляет определенный интерес. В простейшем
случае вся информация пишется в текстовый файл «как есть». Недостаток метода
в том, что вся информация открытая. Это облегчает анализ алгоритмов работы программы
даже при отсутствии исходников.
Если совсем немного доработать код – можно записывать файл в сжатом виде. Мы
использовали замечательную библиотеку Zlib. Она позволяет буквально парой строчек
кода записать архивный файл. Также можно применять простейшие алгоритмы шифрования,
чтобы скрыть содержимое файла от пользователя. Недостаток метода очевиден –
при сжатии сильно снижается скорость работы. Потери производительности могут
быть огромными, т.к. объем отладочной информации значительный.
После разных экспериментов и апробации системы протоколирования, мы остановились
на обычном текстовом файле без всяких излишеств.
Еще один аспект, на который надо обратить внимание при разработке подобной
системы – включение протоколирования по запросу. Во время штатной работы с приложением
запись в файл сообщений не ведется. Пользователь даже не подозревает о ее наличии.
Теперь предположим, что у пользователя возникла проблема и ее не удается решить
обычным образом.
В этом случае служба технической поддержки отправляет пользователю небольшую
утилиту, которая включает протоколирование. Это можно сделать, например, установкой
флага в реестре. После решения проблемы (или после инсталляции новой версии)
протоколирование отключается.
В последних наших разработках использовался еще более интересный подход. Мы
не делали запись в файл. В случае проблемы мы посылали пользователю утилиту,
которая занималась сбором данных и автоматической отправкой службе поддержки.
Работало это очень просто.
При запуске программа определяла, что запущена утилита для снятия протокола
и направляла весь отладочный вывод в нее с помощью сокетов. После выхода из
программы – пользователь получал запрос на отправку данных разработчикам. Очень
удобно.
Обратите еще внимание на важность ошибки (int iDebugLevel). Утилита, которая
отвечает за включение протоколирования, может запросить вывод только ошибок
нужного типа.
Очень важно, чтобы библиотека для протоколирования работы программы была многопоточной.
Заключение
Протоколирование работы приложения – полезный инструмент разработчика. Даже
в примитивном варианте он позволяет экономить массу времени на поиск ошибок
на стороне клиента.
Эту идею можно развить и написать Фреймворк. Например, по файлу протокола можно
реконструировать стек вызовов, переключение потоков и т.п. Хотя я не представляю,
в каких случаях могут понадобиться такие функции.
Полезные материалы
Коментарии к статье|
Не понял, зачем писать номер строки и имя файла.
У меня лог пишется в формате \"время функция() - сообщение\\r\\n\". Если класс, то вместо функции строка \"класс::метод()\". Из имени функции легко определить, что это за функция и где она. В крайнем случае - поиск. А внутри функции строку с этим сообщением (а оно обычно уникально) - найти запросто.
В логах меня удручает только одно - необходимость хранения тонн текста всех возможных сообщений внутри EXE. От этого я начал обдумывать возможность высылки только кода сообщения, с хранением текста отдельно либо в такой вот утилите TCP/IP, меняющей коды на текст сохраняялог. | |
Номер строки и имя файла пишеться исключительно ради простоты навигации по исходникам. Размер проекта превышал 100 000 строк и это просто казалось удобным. Безусловно найти место в программе можно и по более скудной информации. У меня не стоял вопрос размера файла.
Тонны текста можно не хранить - все уже изобретенно до нас. Надо просто посмотреть, как логи пишет Windows. Там фактически пишеться только код ошибки. А все строки храняться в отдельной dll. Правда в этом случае нужна доп. утилита для просмотра лога и расшифровки кодов сообщений и параметров. | |
Кстати еще полезно писать ИД потока. Очень помогает в отладке многопоточных приложений.
Одно время я думал о записи кодированного лог-файла и специальной утилиты для просмотра. Это открывает интересные возможности. Например, можно реконструировать стек вызова для любой записи. | |
Кстати, одна банальная мелочь, о которой я не сразу догадался: нужно отключить буферизацию вывода в файл лога, иначе при крахе программы можно потерять до пары секунд. А это очень плохо, если потеряется момент перед \"концом\".
А имея утилиту расшифровки лога, можно даже писать бинарный лог, экономя на месте. Может даже функции обозначать кодами. Это интересно в случае, если нужно большой объём. Однажды я сделал лог 40 Мб за 12 секунд :) | |
| Да, про буферизацию вы абсолютно правы. Ее можно или отключить, либо делать flush после каждой операции записи в файл. | |
| *ставится фильтр на необработанные исключения | |
| Отключать буферизацию считаю плохой идеей. Ставится просто свой фильтр на необработанные в котором можно сделать flush. Можно еще также добавить в ф-цию логирования когда происходит логирование с кодом ERROR или FATAL_ERROR (как у вас там будут ошибки называться) то делать flush, а для всех остальных использовать буферезацию. Это значительно повышает производительность. А вообще программа тупо закрываться с сообщением об ошибке Windows никогда не должна. ЛЮБАЯ ошибка должна быть перехвачена и если она обработана быть не может то хотя бы должно быть выведено диалоговое окно с неким текстом например лога, выслать который пользователь может в саппорт. Лично я лог вообще не пишу в файл, он у меня хранится в оперативке. Просто когда размер лога в памяти превышает определенный мною размер, то старые записи удаляются. Например, в релизной версии у пользователя включено логирование только с ошибками, т.е. логирование INFO и WARNING вообще не выполняется и, следовательно, падение производительности абсолютно никакого нет и дополнительные затраты оперативки на логирование отсутствуют также . Зато если возникает ошибка (например исключение), то идет полный сбор всей информации об ошибке с раскруткой стека и т.п. и выводится пользователю окно с просьбой выслать сведения об ошибке в отдел техподдержки. Часто пользователь даже не может второй раз воспроизвести возникшую ошибку, но это далеко не повод чтобы ее игнорировать. Если же информации по логированию в режиме ERROR-ONLY недостаточно, то просится пользователя запустить программу с доп. ключами которые включают доп. логирование, но этот режим используется только для отладки программы на стороне клиента, а также для воспроизведения у него ошибки |
|
