Using Graylog and NLog to collect logs from C # applications. Personal experience


KDPV

Habr, welcome!

The following is by no means a tutorial or best practice . I decided only to aggregate and document my achievements in the question posed.

I hope that the contents of this article will allow those seeking information on logging to learn something new or make some decision. And, of course, I hope to get a constructive feedback from the community. It gives a chance to do something better.

For what? For whom?


I’ll try to describe what logging is in my own words:
Saving some human-readable information about a positive or negative event during the execution of the program code, possibly with the preservation of qualitative or quantitative indicators and data as part of the stored information with reference to the time of the event.
A complicated formulation came out, but in the general case it fully describes the task of creating and maintaining logs. High-quality logging helps the developer to control the internal state of the code at any stage of his life: from debug to installation in an unknown environment of the consumer's computer.

Well, let's show how I write logs.

Tools


We omit the consideration of logging using low-informative text messages such as “ Database is not available ,” “ Failed to save the file, ” and the like. Logs of this type are easy to create, but they are often not enough to understand the essence and sources of the problem in the code or environment. At some point, every developer just needs to come up with structured logging. As my good friend and IT mentor told me: “ Collect everything, then exclude unnecessary ... ” Specialized frameworks will help us with this.

There are enough of them. Most of them have similar capabilities and limitations. A lot of articles and reviews have been written about them., comparisons and manuals. For logging in applications written in C # I once chose NLog . Now I don’t remember why it was him, but it just so happened.

This platform has very good documentation and extremely useful use cases . Naturally, at different times and for different projects, I used NLog in different ways. But at some point a code was born that is now used as a snippet and practically does not change.

Implementation


To business! Show the code:
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;
			}
		}
}

Usage example:
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 ...;
			}
		}
	}

Some details


The bare code, albeit with comments, is not cool. Therefore, I will describe a number of conventions and assumptions:

  1. _settings - a certain object of settings. It is not too important how exactly it is formed, but it must be received before the first initialization of the logger.
  2. _logConfig - NLog configuration, performed not in a separate NLog.config file , but directly in the code.

As the documentation says :
NLog will only produce output if having configured one (or more) NLog targets.
Actually, the methods in the Target Methods region are responsible for creating these “goals”:

FileTarget - to write the log to a file.

What does a log file look like?

ColoredConsoleTarget - to output "beautiful" messages to the console (if any).

What does a color console look like?

DebuggerTarget - for outputting logger messages to the Visual Studio output window or to a third-party connected debugger in debug mode.

What do NLog messages look like in the debugger?

GraylogHttpTarget - the goal is to send messages to the server with Graylog installed there .

What does a Graylog message look like?

In my first article on Habr, I mentioned the use of Graylog. I would like to dwell on the last goal on the list. It is she who allows you to send messages from the application to the Graylog service using the NLog library. I’ll try to tell you how I personally liked this tool.

About Graylog (a little)


The description of installing and configuring the service will not be included in this article. I can only say that I deployed it in the docker. This is also described in the documentation :

I give you my compose file
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

I will also add an example of setting “Input” in Graylog:

Graylog listens on http traffic on port 12201


Graylog nodes accept data via inputs. Launch or terminate as many inputs as you want here.


my.web.adress.domain 12201 -, . ...

About GELF


GELF - Graylog Extended Log Format. The format of messages that Graylog perceives.

To send something in GELF format to a certain url, you will need to use an additional target . They are presented in the Integrations section of the documentation .

I chose NLog.Targets.GraylogHttp . Installed nuget in the project and was able to use NLog.Targets.GraylogHttp.GraylogHttpTarget in the configuration of its logger.

The very layout for messages I've simplified to a message , but filled ContextProperties his target'a wide range of additional fields:

new TargetPropertyWithContext()  { Name = "someParamName1", Layout = "someStringInfo" },
new TargetPropertyWithContext()  { Name = "someParamName2", Layout = "someNLogLayoutRendered" },
new TargetPropertyWithContext()  { Name = "someParamName3", Layout = (string)SomeMethodThatGetsInfo() }
I specifically used generalized code to make the principle clear: “arbitrary name + arbitrary value”. Value can be successfully "mined" by some method of its own. For example, reading network settings or free space on the system drive. Whatever ...

Bonus


There is an opinion (and I do not dispute it) that logs are most useful when catching errors. The try / catch constructs have been used successfully and in most cases justify themselves. The "error object" itself is filled with debugging information, data about the chain of events when it occurs, and others. It is convenient to read such an object does not always work.

For myself, I developed this solution:

Bonus method to the logger class for sending fields from objects to 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;
		}


Usage example:
log.Debug(BimlibLogger.GetLogEventWithProperties(LogLevel.Debug, log.Name, $"Got the task", message));


What does it look like in Graylog?
exeption_json_dataexception, json.



exception, .



Result


As a result of applying the described approach and a reasonable implementation of the logger calls into the body of the code, we get a centralized log collection with a convenient interface for reading, parsing, and analyzing them. We have a convenient tool for notifications about certain values ​​in the logs.
Also, the usual log-files, which can also be re-read, draw conclusions, do not disappear. It is not a competitor or a replacement for monitoring systems. But now the situation “my application runs on 100+ very different computers in 3+ foreign-language countries and suddenly breaks somewhere” is solved a little easier and much faster.

It's all?


In principle, I told you everything you need for a relatively comfortable logging of your applications. Ready to discuss, get tips.

Thanks for reading. See you in the comments.

UPD : added AsyncWrapper targets to the work on the advicejustmara

All Articles