Jan 2, 2013

Мысли о журналировании

Ведём журнал событий правильно

 
    Идея написать заметку появилась после решения одной проблемы: не работала проприетарная биллинг система, купленная заказчиком. Наш продукт отправляет в эту систему запросы, но на выходе были только невразумительные ошибки.
    В силу отсутствия внятной документации, вся надежда была только на интуицию и лог-информацию, которая эта мега-система должна была где-то хранить. Логи были найдены в самом непредсказуемом и нетривиальном месте и толку от них оказалось довольно мало.
    После окончания этого “детективного расследования” я решил изложить несколько своих мыслей о том, как мне видится логирование в приложениях. Что-то из этого может показаться слишком явным и даже банальным, но как показывает  опыт - реализация логирования во многих приложений оставляет желать лучшего

Большинство советов относится к приложениями, разработанным на Java, но может быть применимо на других платформах.

Храните логи в одном месте


    Пусть по-умолчанию это будет каталог log или journal в корневой папке приложения. Не прячьте логи в директориях вроде:
<somewhere>/<app_dir>/ResPosApi/Service/Etc/
    Если ваше приложение запускается в консольном режиме (или stdout/stderr где-то сохраняется) - сообщите, в какой именно директории будет сохранена эта информация. Если приложение графическое - такую информацию можно отразить в окне About.
Не лишним может быть принудительное перенаправление System.out & System.err в отдельный лог-файл, некоторые сервера приложений так и поступают.

Отобразите основные парамеры конфигурации приложения


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

  • версия вашего приложения и версии важных библиотек (особенно тех, которые могут подгружаться или нет в зависимости от каких-либо условий
  • параметры подключение к БД (пользователь, хост и порт, версия драйвера, размеры пула)
  • используемые порты (jmx, rmi, whatever)
  • Параметры JNDI (какие ресурсы используются)
  • Имена JMS очередей
  • адреса и TCP-порты  или  URL внешних систем и служб
  • таймаута и другие параметры сетевых соединений
  • выбранный тип шифрования или формат передаваемых данных
  • если ваше приложение при запуске устанавливает соедение(я) с внешними системами -сообщите о результатах
  • если какие-то параметры окружения или настройки отсутствуют и/или являются неприемлимыми - сообщите об этом.
Во время отладки или поиска причин сбоев вся эта информация вам очень поможет.

Формат журналов


    Формат журналов может быть любым, главное, чтоб вам и другим пользователям было удобно его читать и искать нужную информацию. Последнее особенно удобно при помощи различных *nix команд (find, grep, awk, sort).
    На мой взгляд, обязательный минимум, кроме самого сообщения, состоит из даты (в читаемом формате), номера потока, имени класса, уровня сообщения.
   Для большинства лог-файлов подходит обычный (plain) формат, но если ваш журнал будет содержать какие-то сообщения со сложной xml или бинарной структурой, есть смысл использовать XML-формат журнала (напр. XMLLayout из log4j) или сделать свой.

Настройки журналирования


    В процессе создания и отладки приложения вам может неоднократно понадобиться возможность регулировать объём и "гранулярность" выводимой в журналы информаци. Хорошей практикой будет иметь возможность изменять параметры журналирования без перезарузки приложения. Особенно полезным это будет после релиза продукта, когда нежелательно (или невозможно) перезапустить рабочее приложения.
   Все популярные фреймворки журналирования (log4j, slf4j, jul) поддерживают загрузку своих настроек из внешних источников - добавьте в своё приложение резидентный модуль (watchdog) для отслеживания изменений и динамической переконфигурации подсистемы журналирования.
    “Хорошим тоном” будет сообщить при запуски приложения - откуда вычитаны текущие настройки.

   В одном из прошлых проектов мной была реализована возможность “подключаться” к приложению (JMX) для просмотра журналов. Можно было “на лету” регулировать уровень журналирования и просматривать текущие события без доступа к удалённым серверам.

Отдельные журналы для некоторых подсистем


   Как показывает опыт - довольно удобно иметь отдельные журналы для некоторых подсистем. Эти журналы могут отображать взаимодействие с какой-либо внешней системой (биллинг, внешняя “железка”) или отдельной частью вашего распределённого приложения.
    Для удобства - формат хранения и отображения данных может отличаться от основного журнала. Поверьте, это будет очень полезно при отладке и/или разрешении каких-либо проблем с интеграцией!

Сколько и в каком виде хранить журналы


    В процессе работы ваше приложение может генерировать большой объем информации. Если вам понадобится быстро найти информацию за определённый промежуток времени - позаботьтесь о том, чтобы вы смогли быстро найти нужный файл - например настройте параметры ротации журналов по дням (или даже часам, если информации очень много).
Сравните формат: с датами
> ls -all
rw-rw--- 1 user group 8153500 Dec 19 23:37 servicemix.log.121219-220057887
rw-rw--- 1 user group 8154545 Dec 20 23:38 servicemix.log.121220-220041338
rw-rw--- 1 user group 8332235 Dec 21 23:38 servicemix.log.121221-220059497
rw-rw--- 1 user group 7543442 Dec 22 23:37 servicemix.log.121222-121543443
rw-rw--- 1 user group 7712374 Dec 23 23:38 servicemix.log.121223-220038682
rw-rw--- 1 user group 8254541 Dec 24 23:38 servicemix.log.121224-220033353
rw-rw--- 1 user group 7953545 Dec 25 23:37 servicemix.log.121225-220053383
rw-rw--- 1 user group 8135454 Dec 26 23:38 servicemix.log.121226-220037130
и без:
> ls -all
rw-rw--- 1 user group 8153500 Dec 19 23:37 servicemix.log.1
rw-rw--- 1 user group 8154545 Dec 20 23:38 servicemix.log.2
rw-rw--- 1 user group 8332235 Dec 21 23:38 servicemix.log.3
rw-rw--- 1 user group 7543442 Dec 22 23:37 servicemix.log.4
rw-rw--- 1 user group 7712374 Dec 23 23:38 servicemix.log.5
rw-rw--- 1 user group 8254541 Dec 24 23:38 servicemix.log.6
rw-rw--- 1 user group 7953545 Dec 25 23:37 servicemix.log.7
rw-rw--- 1 user group 8135454 Dec 26 23:38 servicemix.log
Если поток информации большой и размер файлов превышает 20-30 мб - не лишним будет ввести ограничение по объему файлов.

Возвращаясь к прошлому проекту - наш архитектор пошёл ещё дальше и объеденил оба подхода - можно было настраивать ротацию журнала и по времени и по размеру файла (DailySizeRollingFileAppender). Если размер превышал указанный предел - журнал продолжал записываться в новый файл. При этом каждый файл содержал точную временную метку начала записи, таким образом, среди набора файлов (см. пример выше) было легко найти информацию за нужный период.

Контексты (MDC, NDC, etc...)


    При грамотном использовании - контектсы становятся хорошими помощниками для отражения дополнительной мета-информации о контексте работы программы в какой-то момент времени:

  • имя пользователя, в чьей сессии произошло событие
  • id или адрес клиента, обработка сообщений от которого вызвало цепочку событий
  • порядковый номер, чтобы выделить события из конкретного контекста


Пара мелочей


Если вы перехватываете exception - запишите его корректно:
try {
    Integer x = null;
    ++x;
} catch (Exception e) {
    log.error("", e);       
<!-- OR  -->
    log.error("Error reading configuration file", e);       
}

Не выводите сообщения вида “Exception occurred” или “Fatal error” - добавьте немного конкретики.
    И ещё, может быть банально, но не стоит отображать в журналах чувствительную информацию: пароли, номер кредиток, личные адреса и телефоны, медицинские и страховые данные, номера авто.
Если же это всё таки необходимо для отладки - маскируйте данные, например телефон +380501234567 можно отобразить как +3805012*****7 и т.д.

Собственно всё, спасибо за внимание! :)

Links