Pull to refresh

Архитектура логирования

Reading time 10 min
Views 118K
Мой опыт разработки в основном строится вокруг разнообразных сетевых cервисов под Windows и Linux. Я обычно стремлюсь добиться максимальной кроссплатформенности вплоть до бинарной совместимости. И конечно, накопилось некоторое количество стабильных решений связанных с логированием.

Топик написан как продолжение к этой статье и будет полезен в первую очередь начинающим программистам.

Здесь я собираюсь осветить следующие вопросы:
  • Внутреннее свойство логгера и примеры софта который его использует.
  • Объемы, уровни и детализация сообщений лога.
  • Общие правила конфигурации в разработке, в бою и в расследовании.



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

Кстати, log4net продолжает развиваться.

Собственно, требуемых дополнений к «Фичам добропорядочного логгера» всего два:
  1. Наблюдение/перезагрузка файла конфигурации — это уже не просто полезное, а весьма необходимое умение.
  2. Минимальное вмешательство в выключенном состоянии.


Под капотом NLog


Сразу обсудим полезность второй фичи.

Часто, при разработке кода, возникает необходимость посмотреть значение какой либо переменной в процессе выполнения. Обычно, используют дебаггер и останавливают программу в интересующем месте. Для меня же, это явный признак, что этом месте будет полезен Trace вывод. В комплекте с юнит-тестами мы сразу получаем развертку этой переменной во времени и протокол для сравнения с тестами в других условиях. Таким образом, дебаггером я практически не пользуюсь.

Очевидно, что в боевом применении, даже выключенное подробное логирование, может мешать как скорости выполнения так и параллельности.

В NLog используются следующие приемы:
  • Кэширование уровня логирования в volatile переменной. Это не требует блокировки или синхронизации потоков.
  • Простой метод выяснения необходимости логирования. При некоторых условиях может приводить к inline-вставке кода в процессе jit-компиляции. А это превращает логику в простой условный пропуск участка кода и избавляет от копирования и передачи параметров функции логирования.
  • Подробные перегрузки методов логирования. Минимизируют преобразование типов, а также берегут от напрасного боксинга, до того как мы выяснили о необходимости логирования.
  • Отложенная генерация сообщения делегатом. Позволяет наглядно и легко задавать сложную генерацию сообщений.


Исходный код класса можно посмотреть тут.

Отлично! Для NLog можно быть уверенным, что ваши сколь угодно детальные сообщения могут быть отключены и это минимально скажется на производительности. Но, это не повод посвящать логированию половину кода.

Что и как логировать



Следует придерживаться правил:

  • Вывод в лог следует размещать на отдельной строке.
  • Сообщение должно быть максимально коротким и информативным.
  • Локализовывать можно только редкие или фатальные сообщения.
  • Аргументы желательно брать из локальных переменных метода или внутренних переменных класса данного метода.
  • Не желательно использовать преобразования типов.


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

Простой пример (фрагмент некоторого класса):
private static Logger Log = LogManager.GetCurrentClassLogger();<br/>
 <br/>
public string Request(string cmd, string getParams)<br/>
{<br/>
    Uri uri = new Uri(_baseUri, cmd + "?" + getParams);<br/>
    Log.Debug("Request for uri:`{0}'", uri);<br/>
    HttpWebRequest webReq = (HttpWebRequest)WebRequest.Create(uri);<br/>
    webReq.Method = "GET";<br/>
    webReq.Timeout = _to;<br/>
 <br/>
    string respText;<br/>
    try<br/>
    {<br/>
        string page;<br/>
        using (WebResponse resp = webReq.GetResponse())<br/>
        using (Stream respS = resp.GetResponseStream())<br/>
        using (StreamReader sr = new StreamReader(respS))<br/>
            page = sr.ReadToEnd();<br/>
        Log.Trace("Response page:`{0}'", page);<br/>
        return page;<br/>
    }<br/>
    catch(Exception err)<br/>
    {<br/>
        Log.Warn("Request for uri:`{0}' exception: {1}", uri, err.Message);<br/>
        throw;<br/>
    }<br/>
}



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

Вообще, в текущем обработчике ошибок полезно детализировать контекст который к привел к исключению и специфичные особенности исключения. В примере было бы полезно вывести поле Status для случая WebException.

Гарантии сохранности лога


Несмотря на некоторые возможности NLog по авто записи логов, нет гарантии сохранности лога при завершении процесса.

Что интересно, попытка завершить запись обработкой события AppDomain.ProcessExit не совсем корректна. В конфигурации может быть настроено много разных способов записи в лог, в том числе и по сети. А обработчик этого события находится в ограниченном окружении. В .Net это время работы не более 2х секунд, а в Mono это остановленный ThreadPool. Поэтому, полезно позаботиться о завершении процесса в более дружественном окружении.

Первое, что следует сделать, это обработать событие AppDomain.UnhandledException. В нем следует записать в лог полную информацию об ошибке и вызвать LogManager.Flush(). Обработчик этого события использует тот же поток, который и вызвал исключение, а по окончании, немедленно выгружает приложение.
private static readonly Logger Log = LogManager.GetCurrentClassLogger();<br/>
 <br/>
public static void Main(string[] args)<br/>
{<br/>
    AppDomain.CurrentDomain.UnhandledException += OnUnhandledException;<br/>
    (...)<br/>
    LogManager.Flush();<br/>
}<br/>
 <br/>
static void OnUnhandledException(object sender, UnhandledExceptionEventArgs e)<br/>
{<br/>
    Log.Fatal("Unhandled exception: {0}", e.ExceptionObject);<br/>
    LogManager.Flush();<br/>
}



Кроме того, следует вызывать LogManager.Flush() везде, где потенциально возможно завершение процесса. В конце всех не фоновых потоков.

Если ваше приложение представляет собой win-service или Asp.Net, то следует обработать соответствующие события начала и завершения кода.

Сколько логировать


Серьезная проблема для разработчика. Всегда хочется получать больше информации, но код начинает выглядеть очень плохо. Я руководствуюсь следующими соображениями.

Вывод в лог это по сути комментарий. Логирование уровня Trace по большей части их и заменяет.
Уровни Trace и Debug читают разработчики, а все что выше — техподдержка и админы. Поэтому до уровня Info сообщения должны точно отвечать на вопросы: «Что произошло?», «Почему?» и по возможности «Как исправить?». Особенно это касается ошибок в файлах конфигурации.

Качественный состав уровней логирования уже разобран в предыдущей статье, здесь рассмотрим только количественный состав:
  • Trace — вывод всего подряд. На тот случай, если Debug не позволяет локализовать ошибку. В нем полезно отмечать вызовы разнообразных блокирующих и асинхронных операций.
  • Debug — журналирование моментов вызова «крупных» операций. Старт/остановка потока, запрос пользователя и т.п.
  • Info — разовые операции, которые повторяются крайне редко, но не регулярно. (загрузка конфига, плагина, запуск бэкапа)
  • Warning — неожиданные параметры вызова, странный формат запроса, использование дефолтных значений в замен не корректных. Вообще все, что может свидетельствовать о не штатном использовании.
  • Error — повод для внимания разработчиков. Тут интересно окружение конкретного места ошибки.
  • Fatal — тут и так понятно. Выводим все до чего дотянуться можем, так как дальше приложение работать не будет.


Боевое развертывание



Предположим, разработка дошла до внедрения.
Отложим вопросы ротации логов, размера файлов и глубины истории. Это все очень специфично для каждого проекта и настраивается в зависимости от реальной работы сервиса.

Остановлюсь только на смысловой организации файлов. Их следует разделить на 3 группы. Может потребуется развести логи модулей в разные файлы, но дальше я все равно буду говорить об одном файле для каждой группы.

  1. Группа Info, с соответствующим уровнем для всех источников. Это информация для администратора. Здесь могут быть следующие вещи: когда приложение стартовало, правильно ли вычитаны конфиги, доступны ли требуемые сервисы, и т.д. Его основное свойство: файл изменяет размер только при перезагрузке приложения. В процессе работы, файл расти не должен. Это поможет обеспечить автоматизированный внешний контроль успешности запуска приложения. Достаточно проверить отсутствие в файле ключевых слов Error и Fatal. Проверка всегда будет занимать предсказуемо малое время.
  2. Группа Warning. Это тоже информация для администратора. Этот файл при нормальной работе должен отсутствовать или быть пустым. Соответственно мониторинг его состояния сразу укажет на сбои в работе. Гибко настроив фильтры по разным источникам, можно подобрать достаточно точный критерий, когда вообще следует обратить внимание на сервис.
  3. Группа Наблюдение. Как правило в ходе внедрения выделяются некоторые проблемные модули. Информация от них в детализации Debug как раз и направляется сюда.


Если приложение успешно внедрено, то в работе остаются только первые две группы.

Расследование сбоев


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

Вывод в лог желательно сделать асинхронным.
Пример, боевой настройки.
<nlog autoReload="true"><br/>
  <targets><br/>
    <target name="fileInfo" type="AsyncWrapper" queueLimit="5000" overflowAction="Block"><br/>
      <target type="File" fileName="${basedir}/logs/info.log" /><br/>
    </target><br/>
    <target name="fileWarn" type="AsyncWrapper" queueLimit="5000" overflowAction="Block"><br/>
      <target type="File" fileName="${basedir}/logs/warn.log" /><br/>
    </target><br/>
  </targets><br/>
 <br/>
  <rules><br/>
    <logger name="*" minlevel="Info" writeTo="fileInfo" /><br/>
    <logger name="*" minlevel="Warn" writeTo="fileWarn" /><br/>
  </rules><br/>
</nlog>


При настройке фильтров следует учитывать относительность уровней логирования для каждой из подсистем. Например, некоторый модуль, имея Info сообщение об инициализации, может быть создан для каждого подключенного пользователя. Разумеется, его вывод в Info группу следует ограничить уровнем Warn.

Чего с логгером делать не следует


Логгер должен быть простым и надежным как молоток. И у него должна быть четко очерчена область применения в конкретном проекте. К сожалению, разработчиков часто трудно удержать. Паттерны проектирования, это в основном полезно, но не этом случае. Достаточно часто стал замечать предложения выделить для логгера обобщенный интерфейс (пример) или реализовать обертку в проекте, чтобы отложить муки выбора NLog vs log4net на потом.

Что бы ни было тому причиной, надо точно помнить, что в первую очередь, такие удобства напрочь убивают компилятору возможность оптимизации.

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

Чего же мне еще не хватает в NLog?

  • Дополнительные перегрузки методов логгера, для того чтобы избежать генерации классов лямбда-функций. Хочется иметь вызов вида
    Log.Trace<TArg1, TArg2>(Func<TArg1, TArg2, string> messageCreater, TArg1 arg1, TArg2 arg2)
    Но на текущий момент, самый короткий человекочитаемый вариант подразумевает скрытую генерацию класса:
    Log.Trace(() => MessageCreate(arg1, arg2))
  • Бинарная совместимость. Помогает быстро тестировать сервисы на разных платформах. В NLog очень много инструкций условной компиляции в зависимости от платформы. Т.е. бинарник для Mono может неожиданно работь в DotNet. А очень желательна предсказуемость, хотя бы и в ограниченной комплектации.
  • Условная расширяемость. Понятно, что с бинарной совместимостью придется жертвовать функционалом, но у нас уже есть удобный механизм расширений. Осталось только, чтобы он фильтровал расширения в зависимости от платформы. Вместе с предыдущей возможностью, это еще и дает простое развертывание через копирование директории с IL-бинарниками.
  • Логгирование внутренних сообщений в общем контексте. Был бы полезен список создаваемых в системе логгеров. К сожалению, не уверен, что можно избежать рекурсии. Например, когда вывод в файл начнет писать ошибки вывода в себя же.


NLog, Log4Net, Enterprise Library, SmartInspect...


Разнообразные сравнения логгеров между собой, упускают одну важную деталь.
Важно сравнивать не только ограничения/возможности, но и возможность быстро добавить свои «хотелки».

Поэтому, буду пока дружить с NLog.
Чего и Вам желаю.
Tags:
Hubs:
+25
Comments 18
Comments Comments 18

Articles