Моя мотивация к написанию состоит в том, что хотелось сформулировать строгий принцип, по которому любой участник команды мог бы логгировать ошибки или события так, чтобы это имело смысл для всех остальных в команде. Так как мне выпала участь отвечать за небольшой зоопарк переплетенных между собой приложений - то хотелось быть уверенным, что держишь руку на пульсе и можно легко выхватывать из потока сообщений от системы то, что действительно важно.
Проблема большинства статей на эту тему в том, что они фактически предлагают записывать субъективные ощущения разработчика. Вроде, уровень “Notice” - это уровень для “существенных событий”, но не ошибок. Эээ… а инструкцию, как определять “существенность” где взять? Описание уровней самим RFC syslog просто бессмысленное - "critical - critical conditions". Спасибо, кэп. Есть варианты получше, например “остановка приложения - fatal, надо исправлять что-то - error, аномалия - warning, рядовое событие - info. Такой вариант существенно лучше, но у меня к нему тоже есть претензии, которые я покажу позже, сравнивая с тем, к чему пришел сам.
Alert/Fatal
Первое и очень простое правило следующее: факт неожиданного завершения процесса я записываю как Alert (Fatal) уровень. Важно отметить, что запись делается о факте закрытия приложения, а не о причине - обычно исключении - его вызвавшей. Некоторая путаница может возникать из-за того, что к нему можно приложить убившее его исключение. Также слово “неожиданное” подразумевает неожиданность с точки зрения внутренней логики процесса, а не внешней вызывающей стороны. Т.е. если Вы целенаправленно в силу какой-то технической задумки тормозите процесс с помощью ThreadAbortException или другим специально заведенным для этой цели исключением - это не считается неожиданным, это - часть плана.
Normal -> Limited
Следующий вопрос, который нужно задать: “Нормально ли это событие”? Нормальность определяется функциональной спецификацией приложения. Легко убедиться в том, что событие нормально, если Вы никак не будете на него реагировать, в каких бы количествах оно не происходило. Такие события я отношу к классу Information, это все те скучные записи, что “такой-то залогинился”, “такая-та операция началась”, “такая-то операция завершилась”.
Упоминание про количество в предыдущем абзаце не с проста. Представьте себе, что Ваше приложение связывается по сети с сервером. В целом, все хорошо, но иногда бывает так, что сервер не отвечает. Чтобы решить проблему - достаточно просто повторить запрос еще раз, максимум два. Таким образом, мы фактически считаем нормальным сбои сервера. Для подобных ситуаций я использую уровень Notice - ошибки, с которыми мы смирились. Никто не будет разбираться, почему раз в месяц она происходит, тем не менее следить за тем, что их количество не начинает нарастать - хотелось бы. Таким образом Notice - это события, которые нормальны лишь в ограниченных количествах. Вы можете спросить "Пфф, ну и как же определять количество, до которого события нормальны?" Ответ - никак, потому что это и не нужно. Здесь работает просто сам факт, что мы согласны о том, что существует некий предел, после которого мы как минимум удивимся, почему этих событий так много. Обычно у каждой операции есть основной, "идеальный" сценарий и множество причин, почему он не дойдет до конца. Эти причины нормальны с определенной частотой. Такого предела точно нет, скажем, для количества успешного входа пользователей в систему. Какое-то количество неуспешных попыток входа тоже нормально. Но думаю никто не станет спорить, что есть какая-то цифра - в принципе - для счетчика неуспешных попыток, после которой мы захотим посмотреть, хотя бы просто из любопытства, откуда их столько?
Not normal -> Error -> Input
Давайте рассмотрим ненормальные события. Из них легко можно выделить два подмножества: те, которые делают невозможным продолжение операции - “ошибки” и те, которые не влияют на выполнение алгоритма - “аномалии”.
Под “не влияют” имеется ввиду то, что внешняя вызывающая сторона не имеет ни единого шанса по полученному результату понять, произошла внутри аномалия или нет. Например операция нестрогого Delete. Может оказаться, что записи, которую Вы пытаетесь удалить - уже нет. Это может быть подозрительным, но точно никак не влияет на вызывающую сторону, потому что конечный результат тот, что она и ожидает.
Давайте еще рассмотрим другой пример - метод DocumentUpdate(id). Для нашего случая - “обновить документ по id” - ясно, что счетчик обновленных строк в базе данных должен быть равен строго 1. А теперь представьте себе, как похолодеет Ваша спина, когда по каким-то - неважно каким - причинам вдруг Вы увидите “10547 rows were updated” в операции из примера? И это к тому же никак не видит вызывающая сторона! Которая продолжит работать и дальше, с каждой секундой уничтожая данные. Именно для таких сценариев, я предлагаю использовать уровень Emergency, когда Вам нужно что-то вроде гибрида стоп-крана в поезде и звука сирены воздушной тревоги.
Теперь рассмотрим ошибки. Для них я предлагаю следующее: обозначать как Critical сбои в операциях input направления и как Error - в операциях output направления. Под input понимаются такие операции, которые влияют на внешние модули системы относительно места, из которого вызываются: они меняют или данные или поведение. Например, Вы запрашиваете состояние своего банковского счета. Сколько бы раз Вы его не обновили - для Вас поведение системы и сам счет не изменится - output. И та же самая операция - но сделанная через другой банк, с комиссией - совершенно другая история - каждый просмотр списывает какой-то количество денег с Вашего счета - input. Грубо говоря, это все кроме "R" из CRUD операций либо POST, PATCH, PUT из http протокола.
Если направление не ясно (иначе говоря, "в любой непонятной ситуации") - Error. Я исхожу из того, что система логгирования никогда не должна лгать: за счет этого, Вы всегда уверены, что critical-ошибка - это точно input-сбой, а error-сообщение - в принципе может быть чем угодно.
По моему опыту, сбой input-операции более неприятен, так как всегда привносит некоторую дополнительную неопределенность насчет состояния системы. Плюс есть некоторый шанс, что пользователь даже не будет знать об этом: потому что кто-то решил избегать методов, которые бросают исключения - “исключения зло!” - но забыл проверить код ошибки DocumentUpdateOrError метода.
Конечно же, output-операция тоже может нести серьезные проблемы - работа блокируется, но это, по крайней мере, точно очевидно для вызывающей стороны мгновенно. Да и "упущенную выгоду" люди переживают не так эмоционально, как прямой урон. В примере с тем же банком - прочувствуйте разницу - увидеть ошибку, что "невозможно отобразить счет" либо потратить немного денег и(или) времени - и увидеть ту же саму ошибку.
Таким образом как-то так незаметно разошлись почти все уровни, остался лишь Debug. Его я предлагаю использовать исключительно в ненормальных ситуациях как уровень, куда писать данные для "расследования". Запись о самом факте ошибки - уровень Error или Critical, дополнительные данные о ее контексте - Debug.
Мой опыт так же показал, что нет какого-то особого смысла выделять какие-то особенные причины ошибок вроде "Нет связи с базой данных", что обычно принято записывать как проблема "особой важности". Важность этого события бросается в глаза и так, без всяких дополнительных уровней, когда Вы получаете резкий всплеск количества Error/Critical событий - не нужно быть Шерлоком Холмсом для того, чтобы понять, что проблема существенна и откладывать нельзя. Но если очень нужно - не вижу проблемы прикрутить счетчик таких ошибок и при достижении некоторого количества, скажем, 12 ошибок за последнюю минуту - высылать Emergency и поднимать тревогу.
Чем плох Fatal-Error-Warning?
Выше я упоминал, что у меня есть некоторые претензии к схеме логгирования крэш-ошибка-аномалия-инфо.
Первая претензия в том, что в простой системе мы не может отличить ситуацию сбоя процесса - что конечно плохо - от еще худшей ситуации, когда система начинает идти в разнос. Да, вероятность этого ничтожна, но эта ситуация идеально описывается японской мудростью “Даже если меч понадобится Вам всего один раз - этот раз будет стоить того, чтобы носить его всю жизнь”. Когда происходит крэш приложения, обычно я не прерываю задачи, над которыми команда работает в текущий момент, а просто ставлю таску "разобраться и починить" следующей в очереди. Ситуация "emergency" требует же именно "бросить все" и потому хочется различать их с первого взгляда.
Вторая моя претензия заключается в том, что в такой системе нет хорошего места для Notice’ов в моем определении. Вы не можете с чистой душой отправить их в Information, так как это не совсем “Окей”. Но и сделать их Warning’ами тоже будет так себе идея, так как Вы скорее всего никогда не почините их и они будут просто мозолить глаза, снижая основное предназначение Warning - привлекать внимание к потенциальным проблемам.
Пример
Давайте на парочке простых ситуаций я проиллюстрирую применение моей схемы. Пускай у нас есть приложение, где в текстовом поле нужно указать путь к файлу и кнопка “Окей”. При нажатии приложение должно считать файл, загрузить его в хранилище, обратиться в внешнему сервису, который вычислит, насколько этот файл хорош (чтобы это ни значило) и показать отчет, где будет указан размер этого файла и удельное “качество файла” на байт.
Если такого файла не существует - это проблема пользователя, мы никак не можем влиять на то, что пользователь вводит. Мы ожидаем, что иногда такое будет проскакивать Notice.
Если к файлу нет доступа - это нормально с точки зрения нашей функциональной спецификации, мы не ожидаем, что работать будет исключительно там, где полные права доступа и иногда такое должно случатся. Можно перефразировать по-другому - нам нечего чинить в этой ситуации. Notice
if (!System.IO.File.Exists(path))
{
Log.Notice("Wrong file path: {0}", path);
MessageBox.Show("The file does not exist");
return;
}
byte[] file = null;
try
{
file = System.IO.File.ReadAllBytes(path);
Log.Info("File size: {0} bytes", file.Length);
}
catch (UnauthorizedAccessException ex) //не планируем реагировать
{
Log.Notice(ex);
MessageBox.Show("There is no permission to read the file");
}
catch (Exception ex) //нам нужно реагировать на такой сценарий
{
Log.Error(ex);
MessageBox.Show("[Unified app error message]");
}Если просто почему-то не смогли прочитать файл, но не из-за прав доступа - это Error - надо разбираться и либо устранять причину, либо уточнять спецификацию.
Прочитали файл - заурядное событие Info - мы всегда записываем это событие.
Если не смогли записать файл в базу - мы знаем, что база хандрит - потому закладываем всегда еще две попытки с небольшой задержкой - Notice
Не повезло и в базу так и не записали после всех попыток - Critical - есть надежда на то, что внутри самого метода, событие исключения перехватывалось и в Debug записывались дополнительные сведения. Затем исключение пробрасывалось дальше, к нам, где мы и остановили его путь.
Записали файл и от базы ушло предупреждение, что там место заканчивается или какая другая беда намечается - Warning - самому приложению от этого факта пока ни холодно ни жарко.
const int Attempts = 3;
for (int i = 0; i < Attempts; i++)
{
try
{
string identifier = storage.FileCreate(file);
Log.Info("File was stored: {0}", identifier);
break;
}
catch (Exception ex)
{
if (i < Attempts - 1)
{
Log.Notice(ex);
}
else
{
Log.Critical(ex);
MessageBox.Show("Can not save file");
return;
}
}
}Если не смогли получить ответ от Сервиса - это Error. Тем не менее, у нас есть некоторый выбор как поступить. Мы может полностью прервать операцию и не показывать никакой отчет - Info: "no report" - простой вариант, либо делать более сложную версию отчета - которая в случае неудачи показывает ну хотя бы размер файла Info: "partial report " и место для “удельного качества” скрыто либо явно написано “Не известно”. Это все равно плохо - согласно нашей спецификации, в отчете обязательно “удельное качество”. Отчет без нее - это своего рода навороченное сообщение об ошибке, тем не менее потенциально более полезное, чем просто не показывать ничего. И в логах мы может проследить, что происходило - Error: "file quality service connection", Info: "partial report".
try
{
var quality = service.Analyze(file);
Log.Info("File quality: {0} points", quality);
var qpb /*quality per byte*/ = quality / file.Length;
MessageBox.Show($"L:{file.Length} Q:{quality} QPB:{qpb}");
Log.Info("Report");
}
catch (Exception ex)
{
Log.Error(ex);
MessageBox.Show($"L:{file.Length}");
Log.Info("Report - Partial");
}Я специально уделяю это внимание потому, что может возникать некоторая путаница. Мол, если у нас что-то обернуто в try..catch - значит мы “ожидаем” это событие. Это не совсем так. Обертываем мы как раз для того, чтобы соответствовать другому требованию спецификации - а именно “Приложение не должно аварийно закрываться с экраном смерти”. Если Ваше приложения после неудачного запроса к внешней системе закрывается - то фактически у Вас две проблемы: сама по себе нештатная ситуация с внешним сервисом плюс некачественное приложение-клиент, которое не способно с этим справиться настолько, что погибает. Соответственно об этом Вы и увидите записи Error: "file quality service connection", Fatal: "App screen of death".
В хорошем приложение логи покажут Вам, что произошла ошибка Error:"file quality service connection", а затем - как приложение из этого выкрутилось: Info: "partial report". Если возникает некая неуверенность, считать ли то или иное событие ожидаемым - всегда можно дополнительно проверить вопросом “Является ли это событие следствием другого?”. Если ответ “да” - то это планируемое поведение, т.е. нормальное, в ответ на нештатную ситуацию. Система ведет себя штатно во внештатной ситуации.
На уровне всего приложения нам надо позаботиться, чтобы записывать факты крэша - которые наверняка иногда будут проскакивать.
Заключение
Для того, чтобы любой в команде мог легко вспомнить что куда писать - я составил вот такую таблицу, которую, наверное, стоит приложить к статье как pdf файл - если это будет кому-то интересно?
Я не стал включать в статью мысли о том, как избегать “двойной тревоги” (и “двойного стресса”), если на Вас начинают сыпаться уведомления и с клиента и сервиса, за которые Вы в ответе. Либо наоборот, когда проблема уровня Emergency, но Вы сами никак не можете повлиять на причину, так как причина в подсистеме, за которую отвечают другие люди.
P.S.: С меня плюс в карму каждому, кто укажет на логические нестыковки или противоречия в тексте, используя при этом минимально возможное количество сарказма.