
Для чего? Для кого?
Попробую описать что такое ведение логов своими словами:
Сохранение некой человекочитаемой информации о позитивном или негативном событии в процессе исполнения программного кода, возможно, с сохранением качественных или количественных показателей и данных в составе сохраняемой информации с привязкой ко времени наступления события.
Сложная вышла формулировка, но в общем случае вполне описывает задачу создания и ведения логов. Качественное записывание логов помогает разработчику контролировать внутреннее состояние кода на любом этапе его жизни: от дебага до инсталляции в неизвестном окружении компьютера потребителя.
Что ж, давайте покажу, как я пишу логи.
Инструментарий
Опустим рассмотрение логирования с помощью малоинформативных текстовых сообщений типа “База недоступна”, “Не удалось сохранить файл” и подобных. Логи такого типа несложно создавать, но их часто бывает мало для понимания сути и источников появления проблемы в коде или окружении. В какой-то момент каждому разработчику просто необходимо прийти к структурированному логированию. Как говорил мне мой хороший друг и 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;
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)rn в System.IO.FileInfo.get_Length()rn в 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 ----------------------------
FileTarget fileTarget = FileTarget(header, layout);
config.AddTarget(fileTarget);
config.AddRuleForAllLevels(fileTarget);
#endregion
#region ConsoleTarget ----------------------------
ColoredConsoleTarget consoleTarget = ConsoleTarget(header, layout);
config.AddTarget(consoleTarget);
config.AddRuleForAllLevels(consoleTarget);
#endregion
#region DebuggerTarget ----------------------------
DebuggerTarget debugTarget = DebuggerTarget(header, layout);
config.AddTarget(debugTarget);
config.AddRuleForAllLevels(debugTarget);
#endregion
#region GelfTarget ----------------------------
// Это такая простенькая защита от набивания Graylog лишними логами, пока приложение не боевое
if (_settings.Statistics)
{
GraylogHttpTarget gelfTarget = GelfTarget(headerStr);
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;
}
#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
Graylog nodes accept data via inputs. Launch or terminate as many inputs as you want here.
Организовав проброс с my.web.adress.domain на порт 12201 своей докер-машины, можно получить доступный отовсюду сбощик логов. Но это факультатив и не всем нужно…
Про GELF
GELF — Graylog Extended Log Format. Формат сообщений, которые воспринимает Graylog.
Чтобы отправлять что-либо в формате GELF на некий url потребуется использование дополнительного target’а. Они представлены в разделе Integrations документации.
Я же выбрал NLog.Targets.GraylogHttp. Установил в проект nuget и смог использовать NLog.Targets.GraylogHttp.GraylogHttpTarget в конфигурации своего логгера.
Сам layout для сообщений я упростил до message, но наполнил ContextProperties своего target’а широким набором дополнительных полей:
new TargetPropertyWithContext() { Name = "someParamName1", Layout = "someStringInfo" },
new TargetPropertyWithContext() { Name = "someParamName2", Layout = "someNLogLayoutRendered" },
new TargetPropertyWithContext() { Name = "someParamName3", Layout = (string)SomeMethodThatGetsInfo() }
Специально использовал обобщённый код, чтобы был ясен принцип: «произвольное имя + произвольное значение». Значение может успешно «добываться» каким-нибудь своим методом. Например, чтением сетевых настроек или свободного места на системном диске. Whatever…
Бонус
Бытует мнение (и я его не оспариваю), что логи полезнее всего при отлове ошибок. Конструкции 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, разбитый на поля.
Результат
В итоге применения описанного подхода и разумного внедрения в тело кода вызовов логгера получаем централизованный сбор логов с удобным интерфейсом для их чтения, парсинга, анализа. Имеем удобный инструмент для оповещений об определённых значениях в логах.
Также никуда не деваются привычные log-файлы, которые также можно перечитывать, делать выводы. Это не конкурент и не замена системам мониторинга. Но теперь ситуация «моё приложение работает на 100+ сильно разных компьютерах в 3+ иноязычных странах и вдруг где-то поломалось» решается несколько легче и много быстрее.