Использование 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;
    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 ...;
    			}
    		}
    	}
    

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


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

    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+ иноязычных странах и вдруг где-то поломалось» решается несколько легче и много быстрее.

    Это всё?


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

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

    UPD: добавил в работу target'ов AsyncWrapper по совету justmara
    AdBlock has stolen the banner, but banners are not teeth — they will be back

    More
    Ads

    Comments 39

      +1

      Отличное начало! С почином!


      Теперь масса вопросов.


      1. Почему грейлог? А не, скажем, эластик? Мне первый нравится самому больше, т.к. это более законченное решение. Но elk как платформа становится все более и более распространенной. А с эксплуатационной точки зрения грейлог имеет сложности эксплуатации и монги, и эластика.
      2. Что будет, если грейлог "ушел"? Мы же не блокируемся на отпралке лога? Значит, мы его теряем.
      3. Нужно (мое мнение) четко отделять события и логи. Условно — если у нас разработка, то нам вообще в первую очередь нужна инфа о падениях. А лучше всего эту задачу решает такая штука как sentry. Да, он-премис она бесплатна. С другой стороны в предыдущем пункте я затронул гарантии доставки. И понятно, что если логи чувствительные, то таким наколенным решением не обойтись и нужно продумывать всю систему.
        0
        Вечер добрый. :) Спасибо.
        Масса ответов.
        1. Под капотомм Грейлога как раз живёт эластик и монго. Просто морда понравилась.
        Сложности эксплуатации на весьма большую долю решаются тем, что грейлог поддерживает связывание в «кластер». Каждый экземпляр — одна нода. Если с ней проблемы, но слушать может другая.
        2. Да. Вероятность такой ситуации возможна. Но ведь есть файлик с логом! :)
        И как раз начал работать над логами в режиме NLog->RabbitMQ->Graylog. А это уже гораздо надёжнее. +из пункта выше ноды…
        3. Признаюсь, с sentry не знаком. Есть такое упущение. В любом случае я заострил внимание на разумности сбора сообщений. + в некоторых случаях внешний мониторинг с обратной связью не применим (параноидальные настройки сети на предприятиях, например...).

        В любом случае решение не самое идеальное и, возможно, не охватывает все варианты использования и ситуации, но… для удовлетворения базовых потребностей в контроле своих продуктов подходит. :)
        Спасибо за реакцию. Наводит на размышления.
          0
          1. я про это и говорю — сложность грейлога = сложность всех компонентов. Потому что если оно сломается, то придется искать что и где развалилось.
          2. Может все-таки RabbitMQ -> Kafka заменить ?
          3. sentry — необязательно использовать ВНЕ контура, можно им уведомлялки слать и на корп почту — главная фишка, что он схлопывает все однотипные проблемы, что позволяет понять пофикшена ли какая-то конкретная бага или нет. Грейлог и ЕЛК — это все-таки решения более общие и на них такой функционал напилить можно, но… зачем? Пускай каждую задачу решает то, что лучше всего для этого подходит )
            0
            1. Абсолютно надёжных систем не бывает в принципе… :) Но я дал для примера файлик для композера: там volume'ы живут отдельно. Поэтому, если сам сервис «испортился» можно «переподнять» весьма быстро. А данные (с высокой вероятностью) должны выжить. Но тут только поиск, только эксперименты.
            2. Думал об этом. Причин не нашёл. Rabbit'а хватает. Честно.
            3. Как раз Грейлог позволяет работать с отчётами, алертами, фильтрами, потоками… :) Этим и привлёк.

            Не буду утверждать, что это конечное решение и я на этом остановлюсь.
              0
              Но я дал для примера файлик для композера: там volume'ы живут отдельно.

              фейспалм — мы тоже долгое время жили на таком же конфиге, но это докер, это компоуз — это не продакшн решение. Скорее на "тесты", "поиграться". На большой нагрузке это все будет проседать. Ну, и менеджить неудобно (потому что те же инпуты добавляются через гуй грейлога, а порты в компоузе надо менять — фу-фу-фу) Поэтому идеально — конечно, когда появятся соответствующие требования — вынести монгу на отдельную виртуалку, эластик — на отдельную. Настраивать это все каким-нибудь ansible playbook'ом

                0
                Ну… не так уж, чтобы совсем фейспалм… :) Масштабирование, прогноз нагрузки, архитектура резервирования — это всё итерационные задачи. Нет предела совершенству. Как разраб, я мониторю жизненные показатели элементов этой системы. Но в определённой степени. В одиночку такая инфраструктура не создаётся и не поддерживается. Поглядим, во что это вырастет.
                Формально с моей стороны «ракеты ушли». Дальше «будем посмотреть». А надёжностью и мощностью агрегатора логов я, конечно же, займусь. Спасибо. :)
                  0

                  Решение с volum'ами банально не масштабируется. Если эти контейнеры уходят в какой-нибудь кубер, да даже банально просто на другом докер-хосте поднимать — сразу возникает вопрос, чтоб эти файлы и там собирались, права/место…
                  Вариант с кроликом тоже плох тем, что в случае проблем сети — мы опять теряем логи (т.е. если nlog не смог достучаться до кролика, или тот перегружен и очередь на отправку растёт == жрёт ресурсы хоста).
                  Т.е. простой вариант — это, например, тот же logstash/filebeats для чтения/отправки логов из файла и на отдельном volume (да, я про его проблемы сказал, но это всё же простой вариант при ограниченом кол-ве хостов). Тот же filebeat будет гарантировать доставку логов после восстановления сети, может отвечать за ротацию итд. С ним тоже проблемы есть, но как вариант на старт — вполне.


                  Дальше развивать есть куда — лучше писать просто в stdout и собирать уже docker logging driver'ом, им же сразу класть в очередь (кролик/кафка/что у вас там ещё есть), чтоб гарантировать доставку и оттуда перекладывать в graylog. Потому что у грейлога тоже могут быть проблемы с приёмом: забитый cpu, забитый elasticsearch, сам грейлог может падать… Так что лучше иметь буфер перед ним тоже. Но это уже другая история про другие объёмы и требования.


                  И ещё — для nlog есть AsyncWrapper.

                    0
                    Решение с volum'ами банально не масштабируется. Если эти контейнеры уходят в какой-нибудь кубер, да даже банально просто на другом докер-хосте поднимать — сразу возникает вопрос, чтоб эти файлы и там собирались, права/место…

                    Сложно с этим спорить. Скорее всего это именно так.
                    Вариант с кроликом тоже плох тем, что в случае проблем сети — мы опять теряем логи (т.е. если nlog не смог достучаться до кролика, или тот перегружен и очередь на отправку растёт == жрёт ресурсы хоста).

                    NLog продолжает писать в файлик. Совсем потерять несколько тяжелее. Но да, вероятность пропусков существует.
                    Т.е. простой вариант — это, например, тот же logstash/filebeats для чтения/отправки логов из файла и на отдельном volume (да, я про его проблемы сказал, но это всё же простой вариант при ограниченом кол-ве хостов). Тот же filebeat будет гарантировать доставку логов после восстановления сети, может отвечать за ротацию итд. С ним тоже проблемы есть, но как вариант на старт — вполне.

                    Можно и так… Но хотелось чего-то простого на стороне исполняемого приложения.
                    Дальше развивать есть куда — лучше писать просто в stdout и собирать уже docker logging driver'ом, им же сразу класть в очередь (кролик/кафка/что у вас там ещё есть), чтоб гарантировать доставку и оттуда перекладывать в graylog. Потому что у грейлога тоже могут быть проблемы с приёмом: забитый cpu, забитый elasticsearch, сам грейлог может падать… Так что лучше иметь буфер перед ним тоже. Но это уже другая история про другие объёмы и требования.

                    Да. Всё так. Но, когда речь о десктоп-приложении docker logging driver'а нет. Вот шлём сразу хоть куда-нибудь. :) Скорее всего позже буду делать это через шину (Rabbit, Kaffka или whatever...)

                    Про AsyncWrapper почитаю. Спасибо. Как-то упустил…
        –2
        Спасибо за статью.
          0

          Спасибо за комментарий. :)

          0
          Отличная связка. Юзаем грейлог уже почти 5 лет, за сутки собираем почти пол миллиона логов. За все это время он ни разу не подвел.
            0
            У нас объёмы пока не такие. Но пока опыт позитивный. :)
              0
              Можно пару вопросов:
              — это только со своих серверов или с клиентских машин тоже?
              — UDP или HTTP?
                0
                Пара ответов:
                — и оттуда, и оттуда.
                — http. Сделали имя третьего уровня, пробросили на 12201 контейнера Graylog.
                  0
                  ОК. http, если с сервера, то наверное ОК, а вот с клиентской машины активное логирование по http не слишком затратно? Или вы «издалека» только ошибки пишете? Как-то буфферизуются запросы к серверу? DSergeev, а как у вас?
                    0
                    Затратно в чём? Траффик? Да не особо… И да — уровень логгирования на продакшене на уровне INFO. Иначе, многовато лишнего.
                    Буферизации не делал сначала, но теперь добавил обёртку асинхронную, где «набивается» очередь сначала. Но она для моих задач не так критична. Правда.
                    Изначально, конечно, хотелось знать, что на «неизвестно-где-стоящем-компе» случился exception. :)
                  0
                  И с серверов и c клиентских приложений.
                  Только UDP, т.к. когда идет большой поток сообщений, то HTTP это слишком долго.
                    0
                    umka-beaf Именно это я имел ввиду с моим «затратно».

                    Какую библиотреку вы используету для UDP посылки в грейлог? Не теряются у вас пакеты?
                +1

                Статик-логгер — это нарушение буковки D в (некночибудетпомянут) solid. Неявная зависимость и всё такое. Давно уже есть microsoft.extensions.logging и даже для такого динозавра как nlog наверняка есть нужные либы.
                Но главный бонус этого microsoft.extensions.logging как раз в том, что можно менять логеры просто настройками, не трогая код приложений (хотя, это как раз и есть то, о чём говорит D).
                Вот представь себе либу, которая вот так статиками использует nlog, в другой также гвоздями прибит log4net, а основное приложение вообще использует serilog. Вот чтоб избежать такого бардака и придуманы абстракции, DI и всё такое.


                И ещё чисто по удобству — почитай про structured logging. Это реально вот прям другой уровень детализации сообщений, передачи контекстов (тот же Scope в microsoft.extensions.logging прям хорошо помогает).

                  0
                  Тут возразить нечего. D нарушена.
                  По поводу microsoft.extensions.logging поясню: это наследие от моей «специализации». При написании плагинов к САПР (Revit, Autocad) приходится балансировать на грани записи информации о событиях и сбора данных. Сбором данных увлекаться не стОит…
                  Либу из своего класса в статье делать никогда и не планировал. Да и контекст hosted assembly он такой себе… Буду считать это для себя следующим шагом. :)
                  structured logging мне как раз и обеспечивает Graylog.
                  Сойдёмся на том, что это один их вариантов. ИМХО, он имеет право на жизнь.
                    0
                    structured logging мне как раз и обеспечивает Graylog.

                    это лишь один конец — отображение. а когда ты пишешь в лог вот таким образом:


                    using _logger.BeginScope("processing user {UserId}", userId);
                    _logger.LogDebug("User {UserName} found", user.Name);

                    а в грейлоге видишь:


                    message: User 123 found
                    Scope: processing user 123
                    UserId: 123
                    UserName: First User

                    при этом не занимаясь ручным наполнением вот этих параметров и не ограничиваясь одним лишь message и тем, что гвоздями забито в GelfTarget. И потом в грейлоге же спокойно ищешь и по UserId и по UserName, потому что они отдельные поля..

                      0
                      NLog поддерживает передачу структур из коробки.
                      при этом не занимаясь ручным наполнением вот этих параметров и не ограничиваясь одним лишь message и тем, что гвоздями забито в GelfTarget. И потом в грейлоге же спокойно ищешь и по UserId и по UserName, потому что они отдельные поля..

                      Не-не-не… Как раз в «бонусном» методе я упрощаю себе жизнь с отправкой чего-то с кучей параметров и свойств. :) И полей в Graylog'е появляется множество, и никакой ручной работы.
                      То, чем набил в настройках GraylogHttpTarget — это то, что паровозом с каждым сообщением улетает. Т.с. базовая информация.
                        0

                        а, ок тогда. просто пример был уж очень упрощён и я, было, подумал, что в nlog для этого какие-то страшные костыли нужны. честно — очень давно его не видел. но хорошо, что до него тоже нормальные практики докатились ;)

                          0
                          :) Он неплох. Как только подведёт, уйду на что-то другое. Обязательно.
                  0
                  Не встречались с проблемой, что грейлог в текущей реализации работает с эластиком в которой точность времени ограничена мс? Из-за этого логи почти любого приложения идут в хаотичном порядке(операции выполняются быстрее чем за мс). Есть ли какое-то решение для этого?
                    0
                    Не встречался. Может кто-нибудь увидит вопрос и подскажет?
                      0
                      Из-за этого на продуктивных серверах все еще используем «старый формат» логирования, потому что порядок сохраняется. Заводил тикет, думал, что связано было с гонками в http, но проблема в том что время в текущем релизе грейлога, точнее эластика с которым он работает(6 вроде) ограничено мс.
                        0
                        Я могу ошибаться, но порядок в сообщениях можно же привязать к timestamp самого сообщения. И порядок появления (следования) сообщений в эластике станет не так важен… Или я не так понимаю проблему?
                        timestamp 2020-04-25 17:35:48 +03:00 — вот такое представление в Грейлоге. Но само поле передаётся NLog'ом: «timestamp»: 1385053862.3072 — точность выше.
                          0
                          По-умолчанию грейлог отображает лог-сообщения с сортировкой по времени, порядок не важен. Только вот в эластике точность 3 знака, а если операция выполняется быстрее миллисекунд, то порядок отображения зависит от времени прихода, тут все начинают ломать асинхронные логгеры. К примеру, у нас есть 2 сообщения следующих таймстампов 1385053862.3072 и 1385053862.3074. Второе должно отобразиться выше. Однако при сохранении данных грейлог запишет у сообщений таймстамп 1385053862.307. Т.к логер асинхронный мы не можем гарантировать, что второе сообщение придет вторым. Вот и получается, что порядок сообщений нарушается. У нас пытались вводить сиквенсы и прочие костыли.
                            0
                            Действительно, такое возможно. Пока у меня ни подобного опыта, ни решения подобной проблемы нет.
                            Искренне надеюсь на Хабр. :) В комментариях много головоломок решалось. Сам видел.
                              +1

                              Не смог оставить этот вопрос.
                              На самом деле при передаче сообщения лога в виде gelf тот же NLog снабжает его sequenceId. По нему можно сортировать сообщения в самом Graylog.
                              Ну и нашёл блог самой Эластики: https://www.elastic.co/blog/journey-support-nanosecond-timestamps-elasticsearch
                              Говорят, что наносекунды реальны. :)
                              Надеюсь Вам это поможет.

                                +1
                                The ability to store dates in nanosecond resolution required a significant refactoring within the Elasticsearch code base. Read this blog post for the why and how on our journey to be able to store dates in nanosecond resolution from Elasticsearch 7.0 onwards.
                                Graylog 3.x does not work with Elasticsearch 7.x!
                                  0
                                  Вот это пропустил. Что ж, тогда либо подождать, либо для выравнивания последовательности сообщений использовать sequenceId.
                      0
                      Очень своевременно, спасибо. Последний месяц активно изучал вопрос Elasticsearch и структурного логирования, и было уже собрался начать скидывать в Elasticsearch свои метрики и логи, как тут вы про грейлог. В главном, чем грейлог выигрывает у «голого» эластика? Я к эластику прикрутил Графану, и вроде все чудесно, даже не знаю чего бы еще захотеть. И еще: посмотрел я на расширения для log4net, NLog и Serilog, какие-то они все такие не особо доверия внушающие: какие-то отдельные люди что-то там когда-то там сделали. На основании чего вы им доверяете?

                        0
                        Рад, что пригодилась моя статья. :)
                        Под капотом Graylog'а и так Elasticsearch. И как раз вчера на 9200 контейнера с Elasticsearch прикрутил Grafan'у. Я, если честно, в неё не особо умею, но попробую… Коллеги её любят, пусть глядят. :)
                        Graylog не то чтобы выигрывает чем-то, а просто чуть удобнее стартовать. Быстрее как-то. Есть удобная web-морда. Вменяемая настройка фильтров и АЛЕРТОВ. Мне очень уж оповещения хотелось об определённых ошибках. Если честно был бы голый ELK, если бы Graylog не встретил и не почитал вечерок.
                        Расширения под перечисленные логгеры естественно пишут люди. Как и сами логгер-библиотеки… Не знаю даже, что тут сказать. На самом деле, кроме NLog я в проекте использую стороннюю target для отправки по http. NLog позволяет custom target создавать… Но опять же, выбрал чуть более простой путь. Объект цели создаётся, в конфигурацию добавляется без ошибок, к просадкам по скорости отправки ничего не добавляет. Не появилось причин не доверять…
                        В комментах уже упоминали гарантированность доставки, но это не сильно к расширениям относится.
                          0
                          Конечно люди пишут. Пока, хвала небесам, машины сами не научились и мы еще для чего-то нужны :) Я в смысле, что расширения бывают официальные внутри продукта или популярные сторонние, им понятно почему можно доверять. А эти какие-то такие… сомнительные вобщем.
                          Спасибо, будем этот грейлог покрутить и посмотреть.
                          Последний эдастик что-то там с алертами умеет, но я не вникал. www.elastic.co/what-is/elasticsearch-alerting
                            0
                            NLog вполне официально говорит про http target и GELF у себя на сайте в разделе Integrations. :)
                            Повторюсь: можно и самому написать отправку под NLog. Я описал, как сам поступил. :)
                            Попробовать Graylog несложно, я и *.yml для быстрого развёртывания подарил.
                            Про алерты в Эластике руки не дошли почитать, может и это использую. Спасибо.
                            0

                            Алерты из логов — это антипаттерн.
                            Ну, ок — если очень хочется — для эластика есть модуль elastalert.
                            Из графаны не рекомендую — она очень приличную нагрузку на БД эластика даёт своими запросами. Такое себе. Либо очень умно планировать нагрузку, либо тюнить запросы.


                            Касательно грейлога — по сравнению с эластиком — это именно, что готовый продукт. Со своими ограничениями, но и очень классными фичами. Типа алертов, потоков, интеграции с лдап и всем прочим. Эластик тоже можно "сварить" со всем нужным, но необходимо тогда погружаться в его специфику


                            Ну, и опять же — вы наверняка не грейлог или эластик хотите, а скорее всего sentry. Он-премис — бесплатно. Попробуйте. Очень крутая штука. Именно для разрабов

                              0
                              Алерты прямо из приложения мне недоступны. Тоже костылестроение.
                              Эластик, как база-хранилище уже используется, хватит с неё. :)
                              Графана пока на уровне «как там мой Graylog, покажешь?». От неё тоже бОльшего не нужно.
                              Тут в комментах про нагрузку многие высказывались, решение всем стОит подбирать по «размеру». :)

                              Касательно грейлога — по сравнению с эластиком — это именно, что готовый продукт. Со своими ограничениями, но и очень классными фичами. Типа алертов, потоков, интеграции с лдап и всем прочим. Эластик тоже можно «сварить» со всем нужным, но необходимо тогда погружаться в его специфику

                              Да. Как-то так на Грейлог и вышел. Вроде легко запустился, вроде всё сразу делает…

                              sentry — мониторинг. Я таки хотел логи.

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