Pull to refresh

Правильное логгирование в Microsoft .NET Framework

.NET *

Зачем нужны логи


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

Примитивный подход


Казалось бы, всё просто:
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 забросили (а жаль).

Выводы


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

Ссылки

Tags:
Hubs:
Total votes 100: ↑77 and ↓23 +54
Views 95K
Comments Comments 40