Web engineer
0,2
рейтинг
9 июля 2010 в 01:33

Разработка → Правильное логгирование в 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 забросили (а жаль).

Выводы


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

Ссылки

@Antelle
карма
206,7
рейтинг 0,2
Web engineer
Реклама помогает поддерживать и развивать наши сервисы

Подробнее
Спецпроект

Самое читаемое Разработка

Комментарии (40)

  • –3
    Э… обычного syslog уже не достаточно?
    • –1
      Вы хотели написать EventLog? Т.к. syslog это «чуждый» протокол для .Net ;-)
      • 0
        Почему же?
        Тот же log4net умеет писать в EventLog, как один из вариантов.
      • 0
        Тьфу. Я хотел написать, «и в syslog», конечно. Если вы работаете под моно.
        • +1
          И даже если не работаете под моно, log4net может писать по UDP в syslog… Но это всё протоколы и места хранения логов (бакэнд) для библиотек логирования. А amarao, насколько я понял, предлагает использовать syslog как «фронтэнд» логирования .net приложений.
  • НЛО прилетело и опубликовало эту надпись здесь
    • 0
      stack trace с вами разговаривает?
    • 0
      А Delphi'йский Stack Trace разве молчит?
      • НЛО прилетело и опубликовало эту надпись здесь
  • +2
    log4net
    </thread>
    • –1
      Аналогично. ColoredConsoleAppender FTW!!!
  • –19
    ява-программисты смеются над этой проблемой
    • +5
      а дотнет разработчики вспоминают, что log4net это порт log4j :)
      • +4
        Ага, log4net, он же log4j, он же log4cxx, он же log4php
        Молодцы Apache, портировали его на несколько языков
        • 0
          Скорее не языков, а платформ ;)
    • 0
      Вспомнилось www.youtube.com/watch?v=gLDFQ_IhnDc
  • +3
    Замечательная статья, всё кратко и по теме. Спасибо.

    > ява-программисты смеются над этой проблемой
    юниксоиды уже в первом каменте посмеялись, тем не менее, качество статьи от этого не уменьшилось: вся прелесть в том, что это не тупое описание отдельного инструмента, а анализ того, зачем нужны логи и как правильно их вести.
  • 0
    Вот с этим я не совсем согласен
    «Log(»При записи истории комментариев для аккаунта {0} в хранилище произошла ошибка, данные за сегодня не будут доступны: {1}", account, ex);"

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

    Такие подробные комментарии мне нравятся для интеграционных методов, даже связь с БД, так как там зависишь, например от процедур, и иногда ошибка возникает только с определенным набором параметров — тогда я просто на уровне связи (с БД — это некий DAL) ловлю ошибки и вместе с ошибкой отправляю имя хранимой процедуры и список параметров (у SqlException есть такая возможность).
  • +1
    А почему не SmartInspect, в приведенном вами обзоре логгеров он вроде сильно выделяется? Сам не использовал его, интересно.
    • 0
      Статья обзор логгеров больше похож на рекламу этого самого SmartInspect
      • 0
        Да, не заметил обилие рекламы вокруг…
      • 0
        Это и есть его реклама, внизу странички — копирайты компании-разработчика. Собственно, потому я и пометил, что почитать оттуда про остальные.
        Явных преимуществ SmartInspect в их сравнении, кстати, я не заметил, основной упор у них на непонятно кому нужный GraphicalViewer.
  • 0
    Спасибо за обзор. Логи — это наше все.
    Смеются только те, кто никогда не доводил свои разработки до внедрения, особенно большие программно-аппаратные комплексы.

    ЗЫ Я бы еще отметил, что грамотный логгер вместе с логом выводит время, контекст потока и модуль/класс, откуда его вызвали. В этом плане, конечно, немыслимым смотрится отсутствие в дотнете-сишарпе простейших макросов, которые бы подставили имя исходника и номер строки. Просто уму непостижимо.

    2010-03-24 12:15:31,349 [9] DEBUG WpfFramework.UIController UpdateMenuNew: WpfFramework.FmMain MainMenu
    • 0
      дык через StackTrace (или как там его) можно узнать откуда вызвали метод «Log». Правда почему логгеры этим не пользуются — хз, видать из-за того что медлено это.
      • 0
        А потому что неудобно это. Контекст вызова должен быть описан в одну строку — это ключевой момент лога. А не в дерево. Ибо обрабатывать это же людям, а у людей на такую обработку — конечное число лет :)
        То есть обычно, есть лог, сто тыщ миллионов строк. На него натравливается grep, и так хоть как-то что-то можно локализовать
    • 0
      Да уж, отсутствие макросов __FILE__ и __LINE__ напрягает.

      Если сборка собрана в режиме отладки, спасает
      string currentFile=new System.Diagnostics.StackTrace(true).GetFrame(0).GetFileName();
      int currentLine = new System.Diagnostics.StackTrace(true).GetFrame(0).GetFileLineNumber();


      В режиме release, увы…
      • 0
        ох позитив какой, спасибо!
      • 0
        Какая разница в каком режиме? Можно и релиз настроить соответствующим образом.
        • 0
          Уточню, — в случае отсутствия отладочной информации.
  • 0
    Для ASP.NET заюзал ELMAH, крайне доволен. Он вообще для unhandled exceptions, но и можно самостоятельно добавлять логи, насколько я понял.
    • 0
      блин что то линки съелись (( вообщем через гугл легко находится + статья есть на мсдн
  • +2
    О log4net.
    А может быть, просто критичных багов не осталось? А портировать это на другие платформы (например, php) более важно.
    Зачем менять то, что и так хорошо работает?
    Последний коммит, кстати, был в ноябре 2009.
  • +2
    Исползую log4net и очень доволен. То, что давно ничего не меняли, может значить, что проект просто дописали до конца и менять больше нечего.
    Да, выше уже писали, но ColoredConsoleAppender — наше все при разработке :)
    • 0
      Возможно, и так. Проект очень хороший, грамотно написанный, лично мне в нём не попалось ни одного бага.
  • +1
    Казалось бы, причем здесь .NET?
    Проблема протоколов есть везде и всегда.
    Кроме того, хотелось бы высказать небольшую мысль на тему сообщений, которые здесь помечены, как Debug:
    В ряде случаев, такие сообщения хорошо позволяют обнаружить место возникновения ошибки. Пример: после каждой успешной операции выдается сообщение такого класса (но, естественно, чтобы логи не разрастались до неприятных размеров, стоит, все же, этот режим сделать отключаемым). Потом внезапно вылезает Error. Все, разработчик по последовательности сообщений однозначно определяет место ошибки и ее характер, плюс, при правильной записи предыдущих сообщений, имеет уже много данных для дебага.

    Причем, такой подход, ИМХО, длинные и ветвистые сообщения не заменят. Во-первых потому, что таких сообщений не попишешь особо много, на каждый случай жизни. Потому что, к примеру, ошибка возникает в генерик классе. И все, привет.

    А во-вторых, если код ОЧЕНЬ большой, то времени на написание таких сообщений тратится существенно больше, чем на организацию вот такого вот поэтапного протоколирования
  • –1
    Удивительно: Хейлсберг (изобретатель C#) и я независимо друг от друга решили кодировать подставляемые параметры как {1}, {2} и т.д.
  • 0
    А в целом — статья правильная. О том, как правильно логировать многозадачные системы, что есть error и чем он отличается от info…
  • 0
    А я использую обычные средства из System.Diagnostics, их возможностей тоже хватает.
    • 0
      Иногда, разумеется, хватает их возможностей. Я показал возможные варианты, если System.Diagnostics будет мало. Может быть, пригодится :)
  • 0
    Хочется добавить что просто создание лога это ещё не всё, если произошла ошибка то надо этот лог своевременно увидеть. Потому рекомендую настроить автоматическую отправку лога ошибок на E-Mail. Напр как указано тут (см. пример 18). Часто исправить ошибку и её последствия, сразу после её возникновения, намного легче чем по прошествии периода времени.

Только зарегистрированные пользователи могут оставлять комментарии. Войдите, пожалуйста.