Зачем нужны логи
Очевидно, что логи делаются для разработчиков, чтобы облегчить им (нам) жизнь. Основные цели, ради которых существуют логи:
- сказать, что же делает система прямо сейчас, не прибегая к помощи отладчика, т.к. это иногда не оправдано;
- провести «расследование» обстоятельств, которые привели к определённому состоянию системы (например, падению или багу);
- проанализировать, на что тратится больше времени/ресурсов, т.е. профилирование.
Примитивный подход
Казалось бы, всё просто:
public static void Log(string message) {
File.AppendAllText("log.txt", message);
}
Зачем что-то ещё придумывать, подключать внешние библиотеки, настраивать конфиги?
На практике, оказывается, что всё не так: одного лог-файла становится уже недостаточно, возникают проблемы с многопоточностью, форматом логов, записью времени, производительностью итд.
Какие же фичи должен поддерживать хороший логгер?
Фичи добропорядочного логгера
Уровни логгирования и фильтрация сообщений
Типичные уровни: Debug, Info, Warn, Error, Fatal
Уровни помогают определить критичность сообщения и приемлемое время реакции на него, об этом подробнее ниже.
Ротация лог-файлов
Логи со временем разрастаются, старые становятся ненужными. Хороший логгер должен уметь подменять активный файл при наступлении определённых условий. Есть два режима: по дате и по размеру файла.
Возможность записи сообщений не только в файлы
Не всегда файл – лучший способ хранения сообщений, хороший логгер должен поддерживать отправку сообщений по протоколу UDP, запись в базу, взаимодействие с очередями сообщений, такими, как MSMQ или JMS. Кроме того, отлично, когда логгер предоставляет возможность реализации собственного потребителя сообщений (обычно это называется термином message consumer, или message appender).
Thread-safety
Потокобезопасность – очень важное требование к логгеру. Плохой логгер может:
- пропустить часть сообщений;
- выбросить исключение
- отрицательно повлиять на производительность
Асинхронное логгирование
Типичная практика логгирования – асинхронная запись. При этом важно, чтобы размер буфера был гибко настраиваемый, например, debug-сообщения можно писать по 100 штук, а error – немедленно после возникновения.
Формат и конфигурация логов
Формат должен быть настраиваемый, с возможностью указать то, что писать и куда писать. Например, можно писать в файл, хранящийся по пути из переменной окружения. Кроме того, полезная фича – динамическая конфигурация логгера, слежение за файлом конфигурации. Надо включить debug-режим – поменяли конфиг и наслаждаемся вкусными логами без перезапуска приложения.
Что и как писать в логи
Фичи логгеров мы рассмотрели. Но чтобы получить хороший, читаемый лог, надо вести логи правильно.
Начнём с того, что обычно «закон» какого-либо сервиса, отдела – это SLA, соглашение об уровнях сервиса (service level agreement). В нём указываются допустимые уровни восстановления после сбоя, время приемлемой реакции на сообщения итд. Чтобы помочь соблюсти SLA и вовремя отреагировать на событие, существуют уровни логгирования.
Уровни логгирования
Очень важно понимать, что любое сообщение несёт в себе информацию определённой критичности, и время реакции на сообщения отличаются. Я приведу пример:
Debug. Отправлен запрос в базу на сохранение
Debug. Завершён запрос в базу на сохранение
Debug. Запрос в базу занял 0.02 секунды, извлечено 1000 записей
Info. Проведена транзакция по счёту 40000000000 (John Doe), получено $2000.
Warn. Отклонена транзакция с суммой платежа 0.
Error. Ошибка при сохранении транзакции 123: …..
Fatal. Не могу запустить модуль отправки исходящих сообщений MSMQ, из-за ошибки конфигурации модуля (…). Транзакции не будут обрабатываться.
Что означает каждый уровень?
Debug: сообщения отладки, профилирования. В production системе обычно сообщения этого уровня включаются при первоначальном запуске системы или для поиска узких мест (bottleneck-ов).
Info: обычные сообщения, информирующие о действиях системы. Реагировать на такие сообщения вообще не надо, но они могут помочь, например, при поиске багов, расследовании интересных ситуаций итд.
Warn: записывая такое сообщение, система пытается привлечь внимание обслуживающего персонала. Произошло что-то странное. Возможно, это новый тип ситуации, ещё не известный системе. Следует разобраться в том, что произошло, что это означает, и отнести ситуацию либо к инфо-сообщению, либо к ошибке. Соответственно, придётся доработать код обработки таких ситуаций.
Error: ошибка в работе системы, требующая вмешательства. Что-то не сохранилось, что-то отвалилось. Необходимо принимать меры довольно быстро! Ошибки этого уровня и выше требуют немедленной записи в лог, чтобы ускорить реакцию на них. Нужно понимать, что ошибка пользователя – это не ошибка системы. Если пользователь ввёл в поле -1, где это не предполагалось – не надо писать об этом в лог ошибок.
Fatal: это особый класс ошибок. Такие ошибки приводят к неработоспособности системы в целом, или неработоспособности одной из подсистем. Чаще всего случаются фатальные ошибки из-за неверной конфигурации или отказов оборудования. Требуют срочной, немедленной реакции. Возможно, следует предусмотреть уведомление о таких ошибках по SMS.
Правильное определение уровней ошибок сказывается на качестве системы и простоте её сопровождения.
Жизненный пример выбора уровней
Давайте представим, что разрабатываемая система – сотрудник почты, который принимает посылки. Принесли посылку.
Debug: Получена посылка 1. Проверяю размер…
Debug: Размер посылки 1: 40x100
Debug: Взвешиваю посылку…
Debug: Вес посылки 1: 1кг
Debug: Проверяю соответствие нормам…
Info (не Error!): Посылка 1 размером 40x100, весом 1кг, отклонена: превышен максимальный размер
…
Info: Посылка 2 размером 20x60, весом 0.5 кг передана на обработку оператору 1
…
Warn: Отказано в обработке для посылки 3: дата на посылке относится к будущему: 2050-01-01
…
Error: Не удалось отдать посылку оператору: оператор не отвечает: таймаут ожидания ответа оператора
…
Fatal: Произошёл отказ весов. Посылки не будут приниматься до восстановления работоспособности.
Логи и исключения
Они неотделимы друг от друга, как Ленин и партия. Обработка исключительных ситуаций или ошибок очень часто нуждается в правильном логгировании.
Плохой пример:
Log(ex.ToString());
Ещё хуже:
Log(ex.Message);
Не пишите исключения без сопроводительного текста в логи. Увидев ни о чём не говорящий stack trace, лично я прихожу в панику. Что это такое – ошибка, уведомление? Как отреагировала программа на это исключение? Продолжила работу в нормальном режиме, упала, ждёт реакции администратора? К сожалению, часто встречаю такое в коде, что весьма печально. Правильный путь:
Log("При записи истории комментариев для аккаунта {0} в хранилище произошла ошибка, данные за сегодня не будут доступны: {1}", account, ex);
Правила записи исключений в логи
- выберите уровень (подсистему), где Вы будете логгировать исключения;
- если вы обработали исключение, возможны три случая:
- исключение считается обработанным и не пробрасывается выше по стеку. В этом случае запишите исключение с подробным стеком в лог;
- исключение пробрасывается выше по стеку в той же подсистеме. Не логгируйте такое исключение. Однако убедитесь, что выше по стеку его запишут;
- исключение пробрасывается выше по стеку в другую подсистему. Например, на другую машину или в другой процесс. Залоггируйте такое исключение, или запишите диагностическое сообщение об исключении;
- если исключение не обрабатывается – не логгируйте его. Однако убедитесь, что выше это исключение будет обязательно залоггировано. Я поясню:
try { … } catch (Exception ex) { Log(ex); throw; }
Ветка catch, в которой один вызов логгера – неверный вариант. Избавьтесь от такого catch.
Эти простые правила помогают не превратить логи в свалку из stack trace-ов при наступлении ошибки.
Да, не забывайте, что ex.ToString() – выведет исключение с текстом и stark trace-ом. Иногда почему-то забывают про этот полезный метод.
Сравнение логгеров
Давайте сравним, что нам предлагают NLog, Log4net, Enterprise Library.
NLog | Log4net | Enterprise Library | |
---|---|---|---|
Лицензия | BSD | Apache | MS-PL |
Уровни | Debug Trace Info Warn Error Fatal |
Debug Info Warn Error Fatal |
Verbose Information Warning Error Critical |
Ротация логов | Да | Да | Да |
Слежение за конфигом | Да | Да | Нет (?) |
Логгирование масивов | Нет | Да | Нет |
Thread safety | Да | Да | Да |
Протоколы | Сеть Память MSMQ База …расширения |
WMI Сеть Память База …расширения |
WMI MSMQ База …расширения |
Буферизация, асинхронное логгирование | Да | Да | Да |
Состояние | Активный | Вероятно, заброшен. Последний баг в багтреке (http://issues.apache.org/jira/) зафиксили в марте 2009 года | Активный |
Ранее я использовал log4net, сейчас перешёл на NLog, т.к. log4net забросили (а жаль).
Выводы
- Не пишите логгер сами;
- изучите конфиги и возможности логгера, который используете;
- правильно выбирайте уровень сообщений в логе;
- следите за логгированием исключений.
Ссылки
- Сравнение логгеров — почитать оттуда можно про NLog, log4net и Enterprise Library
- Принципы логгирования