Logging

В мае 1953 года под Калькуттой в воздухе  разрушился  первый в мире реактивный пассажирский лайнер "Комета-1". Расследуя причины той катастрофы, австралийский учёный Дэвид Уоррен предположил, что записи переговоров членов экипажа, а также показания приборов при падении могли бы помочь в установлении причин крушений самолётов. Несколько лет спустя он создал первый бортовой самописец - устойчивое к повреждениям устройство, записывающее основные полётные параметры самолёта (высота, скорость, отклонение закрылков, тангаж и т.д.), а также звук из кабины. Это устройство позволило установить причины множества авиакатастроф во всём мире и предотвратить будущие трагедии. В настоящее время бортовые самописцы являются обязательными для установки на все гражданские самолёты.

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

Да, я всё ещё помню, что этот блог о программировании! Но логирование относится не только к программированию. На самом деле оно используется для записи состояний различных систем - самолётов, приложений, складов, кораблей, и даже людей (врачи ведут лог принятых пациентами препаратов, а медицинские мониторы отслеживают пульс, давление, температуру и другие параметры пациентов). И везде логирование приследует абсолютно те же цели, что и установка самописцев на авиалайнерах:

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

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

Также важно понимать, что как бы хорошо ни был написан код, в нём всегда могут прятаться какие-то проблемы. И как только (внезапно) наступают определённые условия, скрытые проблемы выходят на поверхность. Поэтому время от времени даже самые качественные приложения падают, как и самолёты (даже слово для этого одинаковое).

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

Лучше приготовиться к тому, что время от времени некоторые модули приложения будут давать сбой, и добавить бортовой самописец - код, записывающий внутреннее состостояние системы (выполняемые действия и их контекст). Обычно это выглядит как-то так:

Console.WriteLine("Starting doing something with x = {0}", x);
DoSomething(x);
Console.WriteLine("Finished doing something");

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

Deposit $100 to account 400001234567899
SELECT * FROM Accounts WHERE Id = 400001234567899
Deposit $0 to account 400001234567899
Transaction rejected: zero amount
Withdraw $50 from account 400001234567899
SELECT * FROM Accounts WHERE Id = 400001234567899
Verifying account type
Cannot withdraw from account:
   SqlException: Could not find stored procedure 'CheckWithdrawPermission'.
Deposit $100 to account 400001234567899
SELECT * FROM Accounts WHERE Id = 400001234567899
Database connection lost:
   SqlException: The server was not found or was not accessible.

Как-то так я себе представляю лог обычного банковского сервиса. Здесь довольно подробно отражена активность приложения: внесение и снятие денег со счёта. Причина падения в данном случае простая - сбой связи с сервером баз данных (это видно по последней записи). Можно также заметить, что не все операции завершились успешно. Более того - можно назвать причины этих проблем. И это не проведя ни секунды времени в отладчике!

Записывать все эти сообщения в лог можно даже с помощью обычного класса Console, либо какого-нибудь StreamWriter:

Console.WriteLine("Withdraw ${0} from account {1}", amount, account);
Console.WriteLine(sqlCommand.CommandText);
Console.WriteLine("Verifying account type");

Но в повседневной жизни очень подробный лог не нужен. В нём сложнее отыскать ошибки, он быстро разрастается, а большое количество логирующих вызовов сказывается на производительности приложения. Поэтому после разработки ненужные вызовы беспощадно удаляются или (чаще всего) комментируются. При возникновении проблем логирующий код возвращают к жизни. А после отладки его снова убирают. В общем, возможности включать и выключать логирование, не внося изменений в исходный код, явно не хватает. Особенно приятно было бы иметь возможность управлять логированием для отдельных классов или модулей приложения. Например, можно избавить лог от подробных команд SQL, если отключить логирование в модуле доступа к данным:

Deposit $100 to account 400001234567899
Deposit $0 to account 400001234567899
Transaction rejected: zero amount
Withdraw $50 from account 400001234567899
Verifying account type
Cannot withdraw from account:
   SqlException: Could not find stored procedure 'CheckWithdrawPermission'.
Deposit $100 to account 400001234567899
Database connection lost:
   SqlException: The server was not found or was not accessible.

Раз уж подробный лог постоянно не нужен, то надо логировать только важные сообщения. Но сейчас степень важности сообщений по логу банковского сервиса определить сложно (там даже сбои найти не легко). Поэтому надо как-то указывать критичность сообщений. Можно особо важные сообщения пометить словом crash, а совсем бесполезные словом trash:

Console.WriteLine("INFO: Deposit ${0} to account {1}", amount, account);
Console.WriteLine("TRASH: {0}", sqlCommand.CommandText);
Console.WriteLine("INFO: Deposit ${0} to account {1}", amount, account);
Console.WriteLine("CRASH: Database connection lost {0}", ex);

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

• FATAL - сообщение о падении приложения. Всё, приложение уже неработоспособно. Смиритесь. Оно как самолёт, у которого отвалились крылья. Осталось только записать побольше информации о состоянии приложения в момент сбоя, чтобы команда спасателей знала - крылья отвалились при попытке подключения к базе данных.
• ERROR - сбой текущей операции. При этом приложение в целом функционирует и не планирует разбиваться о землю. Подумаешь - отказал один из двигателей. Можно перезапустить его, или просто лететь на оставшихся. 
• WARN - что-то требующее внимания, но не приводящее к сбою текущей операции. Например, перевод крупной суммы денег, несколько неудачных попыток входа в систему, или незначительное отклонение давления топлива в двигателе. Все живы, никто не пострадал. Но обратить внимание стоит, во избежание проблем.
• INFO - информационные сообщения. Обычно так сообщают о начале (и завершении) длительных операций, чтобы знать чем занято приложение. Такими сообщениями пилоты информируют, например, о начале новой фазы полёта (запуск двигателей, взлёт, посадка).
• DEBUG - отладочные сообщения. Параметры методов, значения локальных переменных, показания приборов, положение тумблеров - всё, что поможет воссоздать подробный контекст проблемы. Как говорит кэп, используются при отладке.

Когда уровень сообщений указан, найти важные сообщения не составляет труда:

 INFO: Deposit $100 to account 400001234567899
DEBUG: SELECT * FROM Accounts WHERE Id = 400001234567899
 INFO: Deposit $0 to account 400001234567899
 WARN: Transaction rejected: zero amount
 INFO: Withdraw $50 from account 400001234567899
DEBUG: SELECT * FROM Accounts WHERE Id = 400001234567899
DEBUG: Verifying account type
ERROR: Cannot withdraw from account:
   SqlException: Could not find stored procedure 'CheckWithdrawPermission'.
 INFO: Deposit $100 to account 400001234567899
DEBUG: SELECT * FROM Accounts WHERE Id = 400001234567899
FATAL: Database connection lost:
   SqlException: The server was not found or was not accessible.

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

 INFO: Deposit $100 to account 400001234567899
 INFO: Deposit $0 to account 400001234567899
 WARN: Transaction rejected: zero amount
 INFO: Withdraw $50 from account 400001234567899
ERROR: Cannot withdraw from account:
   SqlException: Could not find stored procedure 'CheckWithdrawPermission'.
 INFO: Deposit $100 to account 400001234567899
FATAL: Database connection lost:
   SqlException: The server was not found or was not accessible.

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

 INFO 18:05:29,430 [8] Foo.Domain: Deposit $100 to account 400078
DEBUG 18:05:29,438 [8] Foo.Persistence: SELECT * FROM Accounts WHERE Id = 400078
 INFO 18:05:30,212 [3] Foo.Domain: Deposit $0 to account 400078

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

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

Большинство современных библиотек для логирования бесплатны (и это радует). Остаётся лишь проблема выбора. Вот что хотелось бы получить здесь и сразу:

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

Чтобы решить проблему выбора, я собираюсь рассмотреть самые популярные на платформе .net логирующие библиотеки log4net и nlog, и узнать, какими преимуществами и недостатками они обладают по сравнению с классами из пространства имён System.Diagnostics. Кроме того, я обязательно посмотрю как можно реализовать логирование в аспектно-ориентированном стиле. Но это будет в следующих постах!

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