
КДПВ
Хабр, приветствую!
Описанное ниже ни в коем случае не tutorial или best practice. Я решил всего лишь агрегировать и задокументировать свои достижения в поставленном вопросе.
Надеюсь, содержимое данной статьи позволит ищущим информацию по логированию почерпнуть что-то новое или принять какое-либо решение. И, само собой, надеюсь получить конструктивный фидбек от сообщества. Это даёт шанс делать что-то лучше.
Для чего? Для кого?
Попробую описать что такое ведение логов своими словами:
Сохранение некой человекочитаемой информации о позитивном или негативном событии в процессе исполнения программного кода, возможно, с сохранением качественных или количественных показателей и данных в составе сохраняемой информации с привязкой ко времени наступления события.Сложная вышла формулировка, но в общем случае вполне описывает задачу создания и ведения логов. Качественное записывание логов помогает разработчику контролировать внутреннее состояние кода на любом этапе его жизни: от дебага до инсталляции в неизвестном окружении компьютера потребителя.
Что ж, давайте покажу, как я пишу логи.
Инструментарий
Опустим рассмотрение логирования с помощью малоинформативных текстовых сообщений типа “База недоступна”, “Не удалось сохранить файл” и подобных. Логи такого типа несложно создавать, но их часто бывает мало для понимания сути и источников появления проблемы в коде или окружении. В какой-то момент каждому разработчику просто необходимо прийти к структурированному логированию. Как говорил мне мой хороший друг и IT-наставник: “Собирай всё, лишнее потом исключишь...” В этом нам помогут специализированные framework’и.
Их существует достаточно. У большинства из них схожи возможности и ограничения. Про них написано весьма много статей, обзоров, сравнений и мануалов. Для логирования в приложениях, написанных на C# я в своё время выбрал NLog. Сейчас и не вспомню почему именно его, но так уж сложилось.
У этой платформы весьма неплохая документация и крайне полезные примеры использования. Естественно, в разное время и для разных проектов я использовал NLog по-разному. Но к какому-то моменту родился код, который теперь используется, как сниппет и практически не изменяется.
Реализация
К делу! Покажи код:
using System; using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Linq; using System.Reflection; using System.Runtime.InteropServices; using System.Text; using Newtonsoft.Json; using NLog; using NLog.Config; using NLog.Layouts; using NLog.Targets; using NLog.Targets.GraylogHttp; using NLog.Targets.Wrappers; namespace BIMLIB.Converter { public static class BimlibLogger { private static readonly ApplicationSettings _settings = BimlibSettingsManager.Instance.AppSettings; private static Lazy<LogFactory> _instance = null; private static LoggingConfiguration _logConfig = null; private static Lazy<LogFactory> Instance { get { return _instance ?? (_instance = new Lazy<LogFactory>(BuildLogFactory)); } } public static Logger GetLogger() { return Instance.Value.GetCurrentClassLogger(); } private static LogFactory BuildLogFactory() { LoggingConfiguration config = _logConfig ?? new LoggingConfiguration(); // Не самый обязательный параметр конфигурации. Но так симпатичнее. string headerStr = _settings.LogHeader; // Это только выглядит странным. По факту в заголовке может быть что-то сложное, напрмер: https://github.com/drewnoakes/figgle Layout header = headerStr; // Каждое из этих полей хорошо описано: https://nlog-project.org/config/?tab=layout-renderers // Итог рендеринга такой последовательности полей: // - для простого сообщения: 2020-04-24 19:13:51.1620 [BIMLIB.Converter.MainClass.Main] -> I : Service starting... // - для ошибки: 2020-04-22 09:55:33.1132 [BIMLIB.Converter.Converter.ClearFile] -> E : mscorlib //{ // "Type":"System.IO.FileNotFoundException", "Message":"Файл 'D:\\path\\to\\file\\file_name.ifc' не найден.", "FileName":"D:\\path\\to\\file\\file_name.ifc", "Data":{ // }, "TargetSite":"Void WinIOError(Int32, System.String)", "StackTrace":" в System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)\r\n в System.IO.FileInfo.get_Length()\r\n в BIMLIB.Converter.Converter.ClearFile(String path)", "Source":"mscorlib", "HResult":-2147024894} Layout layout = "${longdate} [${callsite:className=true:includeNamespace=true:fileName=false:includeSourcePath=false:methodName=true:cleanNamesOfAnonymousDelegates=true:cleanNamesOfAsyncContinuations=true}] -> ${level:format=FirstCharacter} : ${message}${onexception:inner=${newline}${exception:format=@}}"; #region Targets ---------------------------- #region FileTarget ---------------------------- Target fileTarget = FileTarget(header, layout).MakeAsyncTarget(); config.AddTarget(fileTarget); config.AddRuleForAllLevels(fileTarget); #endregion #region ConsoleTarget ---------------------------- Target consoleTarget = ConsoleTarget(header, layout).MakeAsyncTarget(); config.AddTarget(consoleTarget); config.AddRuleForAllLevels(consoleTarget); #endregion #region DebuggerTarget ---------------------------- Target debugTarget = DebuggerTarget(header, layout).MakeAsyncTarget(); config.AddTarget(debugTarget); config.AddRuleForAllLevels(debugTarget); #endregion #region GelfTarget ---------------------------- // Это такая простенькая защита от набивания Graylog лишними логами, пока приложение не боевое if (_settings.Statistics) { Target gelfTarget = GelfTarget(headerStr).MakeAsyncTarget(); config.AddTarget(gelfTarget); config.AddRuleForAllLevels(gelfTarget); } #endregion #endregion LogFactory logFactory = new LogFactory { Configuration = config }; try { //Не изящно, но расставляем минимальный и максимальный уровень логирования во все правила логирования config.LoggingRules.ToList().ForEach(r => r.SetLoggingLevels(LogLevel.AllLevels.Min(), LogLevel.AllLevels.Max())); _logConfig = config; } catch (Exception ex) { //Логгера ещё нет, поэтому пока только суда и можно вывести сообщения Debug.Write(ex); } return logFactory; } #region Target Methods private static FileTarget FileTarget(Layout header, Layout layout) { #region FileTarget ---------------------------- FileTarget fileTarget = new FileTarget("log_file_target") { ArchiveAboveSize = 1048576, ArchiveDateFormat = "yyyy.MM.dd_HH.mm.ss", ArchiveEvery = FileArchivePeriod.Day, ArchiveFileName = GetApplicationLogAndArchivePath(false), ArchiveNumbering = ArchiveNumberingMode.Date, ArchiveOldFileOnStartup = false, AutoFlush = true, ConcurrentWrites = true, DeleteOldFileOnStartup = false, EnableArchiveFileCompression = true, EnableFileDelete = true, Encoding = Encoding.UTF8, FileName = GetApplicationLogAndArchivePath(true), Header = header, Layout = layout, MaxArchiveFiles = 100, OpenFileCacheTimeout = 30, OpenFileFlushTimeout = 30, OptimizeBufferReuse = true }; #endregion return fileTarget; } private static ColoredConsoleTarget ConsoleTarget(Layout header, Layout layout) { #region ConsoleTarget ---------------------------- ColoredConsoleTarget consoleTarget = new ColoredConsoleTarget("log_console_target") { Encoding = Encoding.UTF8, EnableAnsiOutput = false, UseDefaultRowHighlightingRules = true, Layout = layout, Header = header }; ConsoleWordHighlightingRule dateHighLightRule = new ConsoleWordHighlightingRule { Regex = @"^(?=\d).+(?=\s\[)", ForegroundColor = ConsoleOutputColor.Yellow }; ConsoleWordHighlightingRule methodsHighLightRule = new ConsoleWordHighlightingRule { Regex = @"(?<=\[).+(?=\])", ForegroundColor = ConsoleOutputColor.Blue }; ConsoleWordHighlightingRule levelHighLightRule = new ConsoleWordHighlightingRule { Regex = @"(?<=>).+(?=\s:)", ForegroundColor = ConsoleOutputColor.Red }; ConsoleWordHighlightingRule messageHighLightRule = new ConsoleWordHighlightingRule { Regex = @"(?<=\s:\s).+", ForegroundColor = ConsoleOutputColor.Green }; consoleTarget.WordHighlightingRules.Add(dateHighLightRule); consoleTarget.WordHighlightingRules.Add(methodsHighLightRule); consoleTarget.WordHighlightingRules.Add(levelHighLightRule); consoleTarget.WordHighlightingRules.Add(messageHighLightRule); #endregion return consoleTarget; } private static DebuggerTarget DebuggerTarget(Layout header, Layout layout) { #region DebuggerTarget ---------------------------- DebuggerTarget debugTarget = new DebuggerTarget("log_debug_target") { Layout = layout, Header = header }; #endregion return debugTarget; } private static GraylogHttpTarget GelfTarget(string header) { #region GelfTarget ---------------------------- Layout gelfCommonLayout = "${message}"; IList<TargetPropertyWithContext> gelfParameterInfos = new List<TargetPropertyWithContext>() { // Все эти дополнительные параметры описаны: https://nlog-project.org/config/?tab=layout-renderers new TargetPropertyWithContext() { Name = "appdomain", Layout = "${appdomain}" }, new TargetPropertyWithContext() { Name = "assembly-version", Layout = "${assembly-version}" }, new TargetPropertyWithContext() { Name = "activityid", Layout = "${activityid}" }, new TargetPropertyWithContext() { Name = "callsite", Layout = "${callsite}" }, new TargetPropertyWithContext() { Name = "callsite-linenumber", Layout = "${callsite-linenumber}" }, new TargetPropertyWithContext() { Name = "environment-user", Layout = "${environment-user:userName=true:domain=true}" }, new TargetPropertyWithContext() { Name = "exeption_json_data", Layout = "${onexception:inner=${exception:format=@}}" }, new TargetPropertyWithContext() { Name = "frameWorkInfo", Layout = $"{RuntimeInformation.FrameworkDescription} ({RuntimeInformation.ProcessArchitecture})" }, new TargetPropertyWithContext() { Name = "guid", Layout = "${guid:format=N}" }, new TargetPropertyWithContext() { Name = "hostname", Layout = "${hostname}" }, new TargetPropertyWithContext() { Name = "identity", Layout = "${identity:authType=true:separator=\n:name=true:isAuthenticated=true}" }, new TargetPropertyWithContext() { Name = "level_name", Layout = "${level:format=Name}" }, new TargetPropertyWithContext() { Name = "local-ip", Layout = "${local-ip:addressFamily=InterNetwork}" }, new TargetPropertyWithContext() { Name = "logger", Layout = "${logger:shortName=false}" }, new TargetPropertyWithContext() { Name = "machinename", Layout = "${machinename}" }, new TargetPropertyWithContext() { Name = "osInfo", Layout = $"{RuntimeInformation.OSDescription} ({RuntimeInformation.OSArchitecture})" }, new TargetPropertyWithContext() { Name = "processid", Layout = "${processid}" }, new TargetPropertyWithContext() { Name = "processinfo_MainWindowHandle", Layout = "${processinfo:property=MainWindowHandle}" }, new TargetPropertyWithContext() { Name = "processinfo_PagedMemorySize", Layout = "${processinfo:property=PagedMemorySize}" }, new TargetPropertyWithContext() { Name = "processname", Layout = "${processname:fullName=true}" }, new TargetPropertyWithContext() { Name = "processtime", Layout = "${processtime:invariant=false}" }, new TargetPropertyWithContext() { Name = "sequenceid", Layout = "${sequenceid}" }, new TargetPropertyWithContext() { Name = "stacktrace", Layout = "${stacktrace:format=Raw:topFrames=3:skipFrames=0:separator= }" }, new TargetPropertyWithContext() { Name = "threadid", Layout = "${threadid}" }, new TargetPropertyWithContext() { Name = "threadname", Layout = "${threadname}" }, new TargetPropertyWithContext() { Name = "timestamp", Layout = $"{DateTimeOffset.UtcNow.ToUnixTimeMilliseconds()}" }, new TargetPropertyWithContext() { Name = "timestamp_local", Layout = @"${date:universalTime=false:format=yyyy-MM-dd HH\:mm\:ss zzz}" }, new TargetPropertyWithContext() { Name = "windows-identity", Layout = "${windows-identity:userName=true:domain=true}" } }; GraylogHttpTarget gelfUdpTarget = new GraylogHttpTarget { AddNLogLevelName = true, Facility = header, GraylogServer = _settings.LogServerAddress, IncludeCallSite = true, IncludeCallSiteStackTrace = true, IncludeEventProperties = true, Layout = gelfCommonLayout, Name = "GelfHttp", OptimizeBufferReuse = true }; foreach (TargetPropertyWithContext gelfParameterInfo in gelfParameterInfos) { gelfUdpTarget.ContextProperties.Add(gelfParameterInfo); } #endregion return gelfUdpTarget; } // Используем обётку https://github.com/nlog/NLog/wiki/AsyncWrapper-target для буферов и асинхронности private static Target MakeAsyncTarget(this Target targ) { return new AsyncTargetWrapper { BatchSize = 100, ForceLockingQueue = true, FullBatchSizeWriteLimit = 5, Name = targ.Name, OptimizeBufferReuse = true, OverflowAction = AsyncTargetWrapperOverflowAction.Grow, QueueLimit = 10000, TimeToSleepBetweenBatches = 1, WrappedTarget = targ }; } #endregion private static string GetApplicationLogAndArchivePath(bool isLog) { string addition; if (!isLog) { addition = ".{#}.zip"; } else { addition = ".log"; } try { if (!Directory.Exists(_settings.LogsFolder)) { Directory.CreateDirectory(_settings.LogsFolder); } return Path.Combine(_settings.LogsFolder, _settings.ProductName + addition); } catch (Exception ex) { Debug.Write(ex); return string.Empty; } } }
Пример использования:
using NLog; ... public static class Downloader { ... private static readonly Logger log = BimlibLogger.GetLogger(); ... public static string GetFileToConvert(ConverterRequest.Inputitem inputItem) { ... try { ... log.Debug($"Downloaded file: {downloadedFile}, size: {new FileInfo(downloadedFile).Length / 1e6}Mb"); } catch (Exception ex) { log.Error(ex, ex.Source); return ...; } } }
Некоторые подробности
Голый код, хоть и с комментариями, — это не круто. Поэтому опишу ряд условностей и допущений:
- _settings — некий объект настроек. Не слишком важно, как именно он формируется, но получен он должен быть раньше первой инициализации логгера.
- _logConfig — конфигурация NLog, выполненная не в отдельном файле NLog.config, а прямо в коде.
Как сказано в документации:
NLog will only produce output if having configured one (or more) NLog targets.Собственно, методы в регионе Target Methods и отвечают за создание этих “целей”:
FileTarget — для записи лога в файл.
Как выглядит log-файл?

ColoredConsoleTarget — для вывода «красивых» сообщений в консоль (при её наличии).
Как выглядит цветная консоль?

DebuggerTarget — для вывода сообщений логгера в output-окно Visual Studio или же в сторонний подключенный дебаггер в режиме отладки.
Как выглядят собщения NLog в отладчике?

GraylogHttpTarget — цель для отправки сообщений на сервер с установленным там Graylog.
Как выглядит Graylog-сообщение?

В своей первой статье на Хабре я упомянул использование Graylog. Я бы хотел остановиться на последней в списке цели. Именно она позволяет отправлять в сервис Graylog сообщения от приложения с помощью NLog-библиотеки. Попробую рассказать, чем мне лично понравился этот инструмент.
Про Graylog (немножко)
Описание установки и настройки сервиса в эту статью не войдёт. Скажу только, что развернул его в докере. Это также описано в документации:
Дарю Вам свой compose-файл
version: '2' services: # MongoDB: https://hub.docker.com/_/mongo/ mongodb: image: mongo:4 restart: always volumes: - mongo_data:/data/db:rw - /etc/localtime:/etc/localtime # Elasticsearch: https://www.elastic.co/guide/en/elasticsearch/reference/6.x/docker.html elasticsearch: image: docker.elastic.co/elasticsearch/elasticsearch-oss:6.8.2 restart: always volumes: - es_data:/usr/share/elasticsearch/data:rw - /etc/localtime:/etc/localtime environment: - http.host=0.0.0.0 - transport.host=localhost - network.host=0.0.0.0 - "ES_JAVA_OPTS=-Xms512m -Xmx512m" ulimits: memlock: soft: -1 hard: -1 mem_limit: 1g # Graylog: https://hub.docker.com/r/graylog/graylog/ # Graylog: I want to have the lastest graylog: image: graylog/graylog:3.2 restart: always volumes: - graylog_data:/usr/share/graylog/data/journal:rw - /etc/localtime:/etc/localtime # Бонус: оповещения в Телеграм. Наверняка и про это как-нибудь расскажу - /home/MYUSER/graylog-data/plugin/graylog-plugin-telegram-notification-2.3.0.jar:/usr/share/graylog/plugin/graylog-plugin-telegram-notification-2.3.0.jar environment: # CHANGE ME (must be at least 16 characters)! - GRAYLOG_PASSWORD_SECRET=somepasswordpepper # Password: MYPASSWORD - GRAYLOG_ROOT_PASSWORD_SHA2=SHA2MYPASSWORDPLEASEINANYONLINESERVICE - GRAYLOG_HTTP_BIND_ADDRESS=0.0.0.0:9999 - GRAYLOG_WEB_LISTEN_URI=http://my.ex.ipa.dr:9999/ - GRAYLOG_HTTP_EXTERNAL_URI=http://my.ex.ipa.dr:9999/ - GRAYLOG_HTTP_PUBLISH_URI=http://my.ex.ipa.dr:9999/ - GRAYLOG_ROOT_TIMEZONE=Europe/Moscow - GRAYLOG_PLUGIN_DIR=plugin links: - mongodb:mongo - elasticsearch depends_on: - mongodb - elasticsearch ports: - 5044:5044 # Graylog web interface and REST API - 9999:9999 # Syslog TCP - 1514:1514 # Syslog UDP - 1514:1514/udp # GELF TCP - 12201:12201 # GELF UDP - 12201:12201/udp #Volumes volumes: mongo_data: driver: local es_data: driver: local graylog_data: driver: local
Добавлю также пример настройки «Input'а» в Graylog:
Graylog слушает http трафик на порте 12201

Организовав проброс с my.web.adress.domain на порт 12201 своей докер-машины, можно получить доступный отовсюду сбощик логов. Но это факультатив и не всем нужно...

Graylog nodes accept data via inputs. Launch or terminate as many inputs as you want here.
Про GELF
GELF — Graylog Extended Log Format. Формат сообщений, которые воспринимает Graylog.
Чтобы отправлять что-либо в формате GELF на некий url потребуется использование дополнительного target'а. Они представлены в разделе Integrations документации.
Я же выбрал NLog.Targets.GraylogHttp. Установил в проект nuget и смог использовать NLog.Targets.GraylogHttp.GraylogHttpTarget в конфигурации своего логгера.
Сам layout для сообщений я упростил до message, но наполнил ContextProperties своего target'а широким набором дополнительных полей:
Специально использовал обобщённый код, чтобы был ясен принцип: «произвольное имя + произвольное значение». Значение может успешно «добываться» каким-нибудь своим методом. Например, чтением сетевых настроек или свободного места на системном диске. Whatever…new TargetPropertyWithContext() { Name = "someParamName1", Layout = "someStringInfo" }, new TargetPropertyWithContext() { Name = "someParamName2", Layout = "someNLogLayoutRendered" }, new TargetPropertyWithContext() { Name = "someParamName3", Layout = (string)SomeMethodThatGetsInfo() }
Бонус
Бытует мнение (и я его не оспариваю), что логи полезнее всего при отлове ошибок. Конструкции try/catch успешно используются и в большинстве случаев оправдывают себя. Сам «объект ошибки» наполнен отладочной информацией, данными о цепочке событий при её возникновении и другим. Удобно читать подобный объект не всегда получается.
Для себя выработал такое решение:
Бонусный метод к классу логгера для отправки в Graylog полей из объектов:
// Метод-бонус. Применяется, когда нужно в Graylog переправить много свойств какого-либо объекта. // На входе среди параметров objWithProps - целевой объект для считывания с него свойств и конвертации их в json (что почти GELF)... public static LogEventInfo GetLogEventWithProperties(LogLevel logLevel, string logName, string message, object objWithProps) { // Можно передать некое текстовое название, а можно и без него обойтись if (string.IsNullOrEmpty(message)) { message = objWithProps?.GetType()?.Name ?? "custom_json_data"; } LogEventInfo e = new LogEventInfo(logLevel, logName, message); object logEventProperty = null; // Здесь много работы для Newtonsoft.Json: https://www.newtonsoft.com/json JsonSerializerSettings jsonSerializerSettings = new JsonSerializerSettings { ReferenceLoopHandling = ReferenceLoopHandling.Serialize, PreserveReferencesHandling = PreserveReferencesHandling.Objects, NullValueHandling = NullValueHandling.Include }; try { // С "простыми" объектами (классами) это проходит легко... logEventProperty = JsonConvert.SerializeObject(objWithProps, Formatting.Indented, jsonSerializerSettings); } catch (Exception ex) { Debug.Write(ex); try { // ...но, если не проходит: считываем свойства, которые этому поддаются, ... IEnumerable<PropertyInfo> objProps = objWithProps?.GetType()?.GetProperties()?.Where(p => p?.GetGetMethod()?.GetParameters()?.Length == 0); if (objProps?.Any() == true) { // ...аккуратно складываем в словарь,... Dictionary<string, string> objPropsDict = objProps .ToDictionary( x => x?.Name, x => { string rezVal = string.Empty; try { rezVal = x?.GetValue(objWithProps, null)?.ToString(); } catch (Exception ex0) { Debug.Write(ex0); } return rezVal; } )? .OrderBy(x => x.Key)? .ToDictionary(obj => obj.Key, obj => obj.Value); // ...и снова работаем Newtonsoft.Json logEventProperty = JsonConvert.SerializeObject(objPropsDict, Formatting.Indented, jsonSerializerSettings); } } catch (Exception ex1) { Debug.Write(ex1); } } // На выходе json-строка, которую Graylog легко превратит в поля сообщения лога. e.Properties["custom_json_data"] = logEventProperty; return e; }
Пример использования:
log.Debug(BimlibLogger.GetLogEventWithProperties(LogLevel.Debug, log.Name, $"Got the task", message));
Как это выглядит в Graylog?
Поле exeption_json_data — exception, превращённый в json.

Тот же exception, разбитый на поля.


Тот же exception, разбитый на поля.

Результат
В итоге применения описанного подхода и разумного внедрения в тело кода вызовов логгера получаем централизованный сбор логов с удобным интерфейсом для их чтения, парсинга, анализа. Имеем удобный инструмент для оповещений об определённых значениях в логах.
Также никуда не деваются привычные log-файлы, которые также можно перечитывать, делать выводы. Это не конкурент и не замена системам мониторинга. Но теперь ситуация «моё приложение работает на 100+ сильно разных компьютерах в 3+ иноязычных странах и вдруг где-то поломалось» решается несколько легче и много быстрее.
Это всё?
В принципе, я рассказал всё, что необходимо для относительно комфортного логирования ваших приложений. Готов обсудить, получить советы.
Спасибо, что прочли. Увидимся в комментариях.
UPD: добавил в работу target'ов AsyncWrapper по совету justmara
