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

Мой опыт разработки в основном строится вокруг разнообразных сетевых 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.
Чего и Вам желаю.

Similar posts

AdBlock has stolen the banner, but banners are not teeth — they will be back

More
Ads

Comments 18

    –3
    Я бы еще добавил про необходимость для Info, Trace и Debug — вызовов предварительно проверять, разрешено ли логирование вызовами методов IsInfoEnabled, IsTraceEnabled и IsDebugEnabled соответственно. Это позволит поднять производительность приложения, когда логи будут выключены на этих уровнях. Для Error и Warn это обычно лишнее (поскольку запись в них происходит относительно редко), а для «информационных» уровней как раз необходимо.
      +3
      Ну это чисто выигрыше в одном вызове. Есть уверенность на 90%, что в Trace и Debug первой же строкой идет проверка Is...Enabled. В общем, только больше кода писать, а в том что дадите какой-то прирост — я очень сильно сомневаюсь.
        +1
        Собственно она там и есть. Я ссылку на исходный код класса привел.
        Необоснованно пока, но предположу, что данном случае методы должны подставляться при jit-копиляции. (что тоже упомянуто)
        Поэтому, предпроверка просто бессмысленна.

        Но все же, пока не дописал бенчмарки, развивать бы эту тему не стал.
          0
          При вызове функции выполняется сбор параметров. А еще иногда для того, чтобы передать что-то в лог, нужно перед этим выполнить дополнительные операции. Если все это можно завернуть в один логический блок, то лучше все же добавить проверку. Иначе дополнительные преобразования будут выполняться впустую. Ну это так уж, эти решения были навеяны отсутствием макросов С++. Как это в С++ — написал макрос LOG, а внутри #ifdef, и при отключенных логах лишнего кода вообще не будет. Ближайший аналог такой оптимизации в C# — ручная проверка перед вызовом самых часто отрабатывающих логов.
            +2
            Именно для этого они сделали в Nlog 2.0 «Lambda-based delayed message computation», а вообще, как и писал автор — сообщение для логирования должно рассчитываться как можно более простым способом.
              0
              Для исключения лишнего кода в C# используйте те же директивы
              #define LOG // обязательно первая строчка файла
              ...
              #ifdef LOG 
              do sth 
              #else 
              do sth else 
              #endif
              
                0
                И вас возненавидят. Качество проекта хорошо определяется по плотности ифдефов на квадратный сантиметр кода
          0
          А мне нравится уникальная фича, реализованная в google log (С++) — можно управлять уровнем логирования не только глобально, но и per-source file (проверяется __FILE__ в точке вызова, результаты кешируются).

          Можно ли это в каком-то виде перенести на managed-платформу?
            0
            В каком-то можно, если у вас есть PDB файлы — тогда можно получать данные о положении функций в стеке относительно файлов и принимать решение на основе этой информации.
            +3
            NLog не кроссплатформенный, у него имеются веселые проблемы с Mono, которые исправлять вроде и не собираются.

            Да, log4net продолжает развиваться, хоть многие и говорили, что он заглох. Я использую именно его. Хоть допилить своими плагинами и оберткой все-таки пришлось, но он гораздо стабильнее.

            Кстати по поводу оберток, где это они убивают возможность оптимизации? Хорошо написанная обертка — просто фасад перед самим логгером. В моем случае, она просто предоставляет тот же GetCurrentClassLogger(), которого в log4net нету и пару плюшек вроде выполнения форматирования сообщения только при включенном логировании уровня. Ну и инкапсуляция, я в любой момент могу перевести весь проект на дрогой логгер, если захочу, без замены кода в 100500 файликах.
            Если хочется еще оптимизировать, достаточно проставить атрибуты Conditional на методы ненужных уровней в обертке. Но в моем случае, мне очень полезны хоть несколько трейсов-дебагов, залогированных перед ошибкой.
              –1
              Это не у NLog проблемы с Моно, а у Моно проблемы, на которые напоролся NLog.
                0
                а я использовал NLog в моне и не заметил особых проблем кроме потока незакрывающегося, которую кстати легко обойти.
                  0
                  На правах рекламы.
                  https://github.com/Belorus/XLog — простенький hi-performance логгер для pcl.
                • UFO just landed and posted this here
                    +1
                    Хочу поделиться парой мыслей по поводу логирования, комментарии приветствуются ;) Правда мои мысли относятся больше к логированию в файлы.
                    Если у вас есть несколько экземпляров вашей службы\приложения на разных машинах — добавляйте «название» машины в имя файла с логом — это потом поможет с меньшей проблемой сливать логи в одно место, правда немножко усложнит их публикацию.
                    Не используйте логгирование для сбора статистики. Тут стоит уточнить один момент… Можно использовать логи для сбора статистики вашего приложения, но не стоит использовать для этого само логирование ;) Это в частности позволит вам делать логи таким образом, что бы они не только легко читались, но и в том числе парсились, и кроме этого отделить логику сбора статистики\мониторинга от самого приложения (собирать статистику должно отдельное приложение).
                    Иногда я вижу, как перед записью в лог экранируются некоторые значения (например затираются пароли в запросе), думаю это частный пример «лишних вычислений», к тому же я считаю, что это ни сколько не увеличивает безопасность (если злоумышленник добрался до логов...). Хотя конечно это касается в первую очередь серверных логоф, на клиенте такое экранирование может быть не лишним (правда логировать такое на клиенте — это тоже отдельная тема).
                      0
                      Спасибо за советы и мысли. логирование мне надо в других вещах, но суть не меняется :)
                        0
                        Спасибо за дополнение.
                        «сбор статистики вашего приложения» — так понял, имели ввиду профилирование (profiling), т.е. контроль производительности.

                        Я для этих целей, настраиваю вывод лога в CSV. Загружаю его в Calc (Excel). Настраиваю фильтры на интересующую операцию. Далее, добавляю колонку, которая вычисляет разницу времени вывода сообщения.

                        Дальше, по обстоятельствам. Но обычно, можно отыскать в каком окружении код начинает резко медленнее работать.
                        +1
                        для обобщенного интерфейса уже есть обертки. CommonLogging вполне себе…

                        Only users with full accounts can post comments. Log in, please.