Использование Graylog и NLog для сбора логов от приложений на C#. Личный опыт

от автора


КДПВ

Хабр, приветствую!

Описанное ниже ни в коем случае не 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;  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 ----------------------------  			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 ...; 			} 		} 	} 

Некоторые подробности

Голый код, хоть и с комментариями, — это не круто. Поэтому опишу ряд условностей и допущений:

  1. _settings — некий объект настроек. Не слишком важно, как именно он формируется, но получен он должен быть раньше первой инициализации логгера.
  2. _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_dataexception, превращённый в json.

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

Результат

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

Это всё?

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

Спасибо, что прочли. Увидимся в комментариях.

ссылка на оригинал статьи https://habr.com/ru/post/498978/


Комментарии

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *