Skip to content

Conversation

@codebrain
Copy link
Contributor

Implement a layout renderer for NLog to emit ECS compatible JSON

@snakefoot
Copy link
Contributor

snakefoot commented Feb 4, 2020

Why not make a custom layout that inherits from JsonLayout. Similar to this:

https://github.com/datalust/nlog-targets-seq/blob/dev/src/NLog.Targets.Seq/CompactJsonLayout.cs

Or this:

https://github.com/newrelic/newrelic-logenricher-dotnet/blob/master/src/NLog/NewRelic.LogEnrichers.NLog/NewRelicJsonLayout.cs

Of course it is recommended to use NLog ver. 4.5.11.

This will make it easy add custom properties besides those included in the custom LogEvent. Ex. ThreadId, MachineName, ${aspnet-request}

@codebrain codebrain self-assigned this Feb 5, 2020
@codebrain
Copy link
Contributor Author

Hi @snakefoot

Thanks for having a look at this PR and offering your suggestion. I have spent some time looking at JsonLayout and seeing if it is something we can support.

The ECS format makes heavy use of nested JSON. A short example below:

{
  "@timestamp": "2019-11-22T14:59:02.5903135+11:00",
  "log.level": "Information",
  "message": "Log message",
  "ecs": {
    "version": "1.4.0"
  },
  "event": {
    "severity": 0,
    "timezone": "AUS Eastern Standard Time",
    "created": "2019-11-22T14:59:02.5903135+11:00"
  },
  "log": {
    "logger": "Elastic.CommonSchema.Serilog"
  }
}

I've been looking for a decent way to represent this nested JSON using JsonLayout and this page https://github.com/NLog/NLog/wiki/JsonLayout#advanced-examples indicates how to achieve this.

So far, so good.

We could extend the code generator to generate a C# JsonLayout from the ECS schema, although we would need to create a map that can associate an ECS entity property with an NLog LayoutRenderer. For example: Base.Timestamp maps to ${longdate}. This would allow us to pre-fill the JsonAttribute values with sensible defaults, and would allow us to maintain the codebase for future generated ECS versions.

We already do something similar for the NEST mapping here:

I also found a complete(?) list of Nlog layout renderers here: https://nlog-project.org/config/?tab=layout-renderers

I am reluctant to generate an NLog XML configuration that the user can incorporate into their app.config and then edit freely. One of the challenges I can see going forward with this approach is how that user will keep their schema up-to-date for future ECS versions. It would be the users responsibility to maintain their XML configuration, and I wonder if this is a good idea for them in the long term.

Have I missed anything here, or does that sound reasonable?

@snakefoot
Copy link
Contributor

snakefoot commented Feb 7, 2020 via email

@codebrain
Copy link
Contributor Author

@snakefoot - what do you think of: d806eb9#diff-0ba4f1a02a13a69ccc7d4cb6f3385a6d ?

@snakefoot
Copy link
Contributor

snakefoot commented Feb 11, 2020 via email

@snakefoot
Copy link
Contributor

Okay now I see that the code comes from something similar to T4-TextTemplate (TT). Thus the custom JsonLayout will be in sync with your schema.

And the result is actually very nice. Just need some syntax sugar to make it easily configurable for users. But protect the schema so users do not destroy it.

Thinking something like this (Instead of dotnet-property-names, then one could also just use dashed_name)

public class EcsSchemaLayout : Layout
{
     private class EscJsonLayout : JsonLayout
     {
           public JsonLayout MetaData { get; }

           // TODO Auto-Generate these properties
           public JsonAttribute AgentVersion { get; } = new JsonAttribute("version", "", true);
           public JsonAttribute AgentName { get; } = new JsonAttribute("name", "", true);
           public JsonAttribute AgentType { get; } = new JsonAttribute("type", "", true);
           public JsonAttribute AgentId { get; } = new JsonAttribute("id", "", true);
           public JsonAttribute AgentEphemeral_id { get; } = new JsonAttribute("ephemeral_id", "", true);

           public EcsJsonLayout()
           {
              // TODO Auto-Add these attributes
              Attributes.Add(new JsonAttribute("agent", new JsonLayout
              {
                 Attributes =
                 {
                    AgentVersion,
                    AgentName,
                    AgentType,
                    AgentId,
                    AgentEphemeral_id,
                 }
              }));

              MetaData = new JsonLayout()
              {
                 IncludeAllProperties = true,
                 IncludeMdlc = false,
                 MaxRecursionLimit = 1,
                 RenderEmptyObject = false,
             }

             Attributes.Add(new JsonAttribute("_metadata", MetaData, false));
         }
     }

     private readonly EscJsonLayout _innerLayout = new EscJsonLayout();

     protected override void RenderFormattedMessage(LogEventInfo logEvent, StringBuilder target)
     {
          _innerLayout.RenderFormattedMessage(logEvent, target);
     }

     public Layout SchemaLayout => _innerLayout; // Necessary for NLog config reflection/initialization

     public bool IncludeAllProperties
     {
         get => _innerLayout.MetaData.IncludeAllProperties;
         set => _innerLayout.MetaData.IncludeAllProperties = value;
     }

     public bool IncludeMdlc
     {
         get => _innerLayout.MetaData.IncludeMdlc;
         set => _innerLayout.MetaData.IncludeMdlc = value;
     }

     public int MaxRecursionLimit
     {
         get => _innerLayout.MetaData.MaxRecursionLimit;
         set => _innerLayout.MetaData.MaxRecursionLimit= value;
     }

     [ArrayParameter(typeof(JsonAttribute), "attribute")]
     public IList<JsonAttribute> Attributes
     {
         get => _innerLayout.MetaData.Attributes;
         set
         {
               _innerLayout.MetaData.Attributes.Clear();
               _innerLayout.MetaData.Attributes.AddRange(value);
         }
     }

     // TODO Auto-Generate these properties
     public Layout AgentVersion
     {
         get => _innerLayout.AgentVersion.Layout;
         set => _innerLayout.AgentVersion.Layout = value;
     }

     public Layout AgentName
     {
         get => _innerLayout.AgentName.Layout;
         set => _innerLayout.AgentName.Layout = value;
     }

     public Layout AgentType
     {
         get => _innerLayout.AgentType.Layout;
         set => _innerLayout.AgentType.Layout = value;
     }

     public Layout AgentId
     {
         get => _innerLayout.AgentId.Layout;
         set => _innerLayout.AgentId.Layout = value;
     }

     public Layout AgentEphemeral_id
     {
         get => _innerLayout.AgentEphemeral_id.Layout;
         set => _innerLayout.AgentEphemeral_id.Layout = value;
     }
}

But when the type is not "keyword" but instead "long" or "double" then the JsonAttribute.Encode = false (instead of true). NLog really loves to output strings, and will automatically add quotes for all JsonAttribute-values, unless Encode = false.

@codebrain
Copy link
Contributor Author

@snakefoot - thank you for your suggestion, it looks like an interesting approach. Leave it with me and let me see what I can come up with in the template and generator.

@snakefoot
Copy link
Contributor

snakefoot commented Feb 14, 2020 via email

@snakefoot
Copy link
Contributor

This is pretty much pseudo-code, that probably won't compile. I have moved the mapping logic from LogEventConverter into the EscLayout.

using System;
using System.Text;
using NLog;
using NLog.Layouts;

namespace Elastic.CommonSchema.NLog
{
    public class EscLayout : Layout
    {
		[ArrayParameter(typeof(TargetPropertyWithContext), "metadata")]
		public IList<TargetPropertyWithContext> MetaData { get; private set; } = new List<TargetPropertyWithContext>();

		[ArrayParameter(typeof(TargetPropertyWithContext), "tag")]
		public IList<TargetPropertyWithContext> Tags { get; private set; } = new List<TargetPropertyWithContext>();

		[ArrayParameter(typeof(TargetPropertyWithContext), "label")]
		public IList<TargetPropertyWithContext> Labels { get; private set; } = new List<TargetPropertyWithContext>();

		public bool IncludeAllProperties { get; set; }

		public Layout EventCategory { get; set; }

		public Layout EventAction { get; set; }

		public Layout EventId { get; set; }

		public Layout EventKind { get; set; }

		public Layout EventSeverity { get; set; }

		public Layout EventSeverity { get; set; }

		public Layout AgentId { get; set; }

		public Layout AgentName { get; set; }

		public Layout AgentType { get; set; }

		public Layout AgentVersion { get; set; }

		public Layout ProcessId { get; set; }

		public Layout ProcessName { get; set; }

		public Layout ProcessTitle { get; set; }

		public Layout ProcessExecutable { get; set; }

		public Layout ProcessThreadId { get; set; }

		public Layout ServerUser { get; set; }

		public Layout ServerAddress { get; set; }

		public Layout ServerIp { get; set; }

		public Layout HostId { get; set; }
		public Layout HostName { get; set; }
		public Layout HostIp { get; set; }

		public Layout ApmTraceId { get; set; }

		public Layout ApmTransactionId { get; set; }

		public Layout UrlOriginal { get; set; }
		public Layout UrlFull { get; set; }
		public Layout UrlDomain { get; set; }
		public Layout UrlPath { get; set; }
		public Layout UrlQuery { get; set; }

		public Layout UserAgentOriginal { get; set; }
		public Layout UserAgentName { get; set; }
		public Layout UserAgentVersion { get; set; }

		public Layout ClientAddress { get; set; }
		public Layout ClientIp { get; set; }
		public Layout ClientDomain { get; set; }

		public EscLayout()
		{
			IncludeAllProperties = true;
			ProcessId = "${processid}";
			ProcessName = "${processname:FullName=false}";
			ProcessExecutable = "${processname:FullName=true}";
			ProcessTitle = "${processinfo:MainWindowTitle}";
			ProcessThreadId = "${threadid}";
			HostName = "${machinename}";
			HostIp = "${local-ip:cachedSeconds=60}";	// NLog 4.6.8
			ServerUser = "${environment-user}";         // NLog 4.6.4
			ApmTraceId = "${ElasticApmTraceId}";                // Consider placing EscLayout into the Elastic.Apm.NLog library (Maybe call it ElasticApmLayout)
			ApmTransactionId = "${ElasticApmTransactionId}";    // Consider placing EscLayout into the Elastic.Apm.NLog library (Maybe call it ElasticApmLayout)
		}

		protected override void RenderFormattedMessage(LogEventInfo logEvent, StringBuilder target)
		{
			var ecsEvent = LogEventConverter.ConvertToEcs(logEvent);    // Creates basic Base + Ecs + Log + Error
			ecsEvent.Agent = GetAgent(logEvent);
			ecsEvent.Event = GetEvent(logEvent);
			ecsEvent.MetaData = GetMetaData(logEvent);
			ecsEvent.Process = GetProcess(logEvent);
			ecsEvent.Server = GetServer(logEvent);
			ecsEvent.Tags = GetTags(logEvent);
			ecsEvent.Labels = GetLabels(logEvent);
			ecsEvent.Url = GetUrl(logEvent);	// TODO
			ecsEvent.UserAgent = GetUserAgent(logEvent);    // TODO
			ecsEvent.Client = GetClient(logEvent);// TODO
			ecsEvent.Trace = GetApmTraceId(logEvent);
			ecsEvent.Transaction = GetApmTransactionId(logEvent);
			var output = ecsEvent.Serialize();
			target.Append(output);
		}

		IDictionary<string, object> GetMetaData(LogEventInfo e)
		{
			if ((IncludeAllProperties && e.HasProperties) || MetaData?.Count > 0)
			{
				IDictionary<string, object> metaData = new Dictionary<string, object>();
				if (e.HasProperties)
				{
					foreach (var prop in e.Properties)
					{
						PopulatePropertyBag(metaData, prop.Key?.ToString(), prop.Value);
					}
				}
				if (MetaData?.Count > 0)
				{
					for (int i = 0; i < MetaData?.Count; ++i)
					{
						var value = MetaData[i].Layout?.Render(e);
						if (!string.IsNullOrEmpty(value) || MetaData[i].IncludeEmptyValue)
						{
						    PopulatePropertyBag(metaData, MetaData[i].Name, value);
					}
				}
				if (metaData.Count > 0)
				       return metaData;
			}

			return null;
		}

		string[] GetTags(LogEventInfo e)
		{
			if (Tags?.Count > 0)
			{
				if (Tags.Count == 1)
				{
					string tag = Tags[0].Layout.Render(e);
					return GetTagsSplitted(tag);
				}
				else
				{
					var tags = new List<string>(Tags.Count);
					for (int i = 0; i < Tags.Count; ++i)
					{
						string tag = Tags[i].Layout.Render(e);
						tags.AddRange(GetTagsSplitted(tag));
					}
					return tags.ToArray();
				}
			}

			return null;
		}

		string[] GetTagsSplitted(string tags)
		{
			if (string.IsNullOrEmpty(tags))
				return Array.Empty<string>();
			else
				return tags.Split(new[] { ';', ',', ' ', '\t', '\n' }, StringSplitOptions.RemoveEmptyEntries);
		}

		IDictionary<string, object> GetLabels(LogEventInfo e)
		{
			if (Labels?.Count > 0)
			{
				IDictionary<string, object> labels = new Dictionary<string, object>();
				for (int i = 0; i < Labels?.Count; ++i)
				{
					var value = Labels[i].Layout?.Render(e);
					if (!string.IsNullOrEmpty(value) || Labels[i].IncludeEmptyValue)
					{
						PopulatePropertyBag(labels, Labels[i].Name, value);
					}
				}
				if (labels.Count > 0)
					return labels;
			}

			return null;
		}

		Event GetEvent(LogEventInfo e)
		{
			var eventCategory = EventCategory?.Render(logEvent);
			var eventSeverity = EventSeverity?.Render(logEvent);

			var evnt = new Event
			{
				Created = e.Timestamp,
				Category = !string.IsNullOrEmpty(eventCategory) ? new[] { eventCategory } : null,
				Action = EventAction?.Render(logEvent),
				Id = EventId?.Render(logEvent),
				Kind = EventKind?.Render(logEvent),
				Severity = !string.IsNullOrEmpty(eventSeverity) ? long.Parse(eventSeverity) : GetSysLogSeverity(e.LogLevel),
				Timezone = TimeZoneInfo.Local.StandardName,
			};

			//Why does this get overriden in full framework?
#if FULLFRAMEWORK
			evnt.Timezone = TimeZone.CurrentTimeZone.StandardName;
#endif
			return evnt;
		}

		private Agent GetAgent(LogEventInfo e)
		{
			var agentId = AgentId?.Render(e);
			var agentName = AgentName?.Render(e);
			var agentType = AgentType?.Render(e);
			var agentVersion = AgentVersion?.Render(e);
			if (string.IsNullOrEmpty(agentId) && string.IsNullOrEmpty(agentName) && string.IsNullOrEmpty(agentType) && string.IsNullOrEmpty(agentVersion))
				return null;

			var agent = new Agent
			{
				Id = agentId,
				Name = agentName,
				Type = agentType,
				Version = agentVersion,
			};

			return agent;
		}

		private Process GetProcess(LogEventInfo e)
        {
			var processId = ProcessId?.Render(e);
			var processName = ProcessName?.Render(e);
			var processTitle = ProcessTitle?.Render(e);
			var processExecutable = ProcessExecutable?.Render(e);
			var processThreadId = ProcessThreadId?.Render(e);
			if (string.IsNullOrEmpty(processId) && string.IsNullOrEmpty(processName) && string.IsNullOrEmpty(processTitle) && string.IsNullOrEmpty(processExecutable) && string.IsNullOrEmpty(processThreadId))
				return null;

			return new Process
			{
				Title = processTitle,
				Name = processName,
				Pid = !string.IsNullOrEmpty(processId) ? long.Parse(processId) : 0,
				Executable = processExecutable,
				Thread = !string.IsNullOrEmpty(processId) ? new ProcessThread { Id = long.Parse(processId) } : null,
			};
		}

		private Server GetServer(LogEventInfo e)

		{
			var serverUser = ServerUser?.Render(e);
			var serverAddress = ServerAddress?.Render(e);
			var serverIp = ServerIp?.Render(e);
			if (string.IsNullOrEmpty(serverUser) && string.IsNullOrEmpty(serverAddress) && string.IsNullOrEmpty(serverIp))
				return null;

			return new Server
			{
				User = !string.IsNullOrEmpty(serverUser) ? new User { Name = serverUser } : null,
				Address = serverAddress,
				Ip = serverIp,
			};
		}

		private Trace GetApmTraceId(LogEventInfo e)

		{
			var traceId = ApmTraceId?.Render(e);
			if (string.IsNullOrEmpty(traceId))
				return null;

			return new Trace { Id = traceId };
		}

		private Trace GetApmTransactionId(LogEventInfo e)
		{
			var transactionId = ApmTransactionId?.Render(e);
			if (string.IsNullOrEmpty(transactionId))
				return null;

			return new Transaction { Id = transactionId };
		}


		private Server GetHost(LogEventInfo e)
		{
			var hostId = HostId?.Render(e);
			var hostName = HostName?.Render(e);
			var hostIp = HostIp?.Render(e);
			if (string.IsNullOrEmpty(hostId) && string.IsNullOrEmpty(hostName) && string.IsNullOrEmpty(hostIp))
				return null;

			var host = new Host
			{
				Id = hostId,
				Name = hostName,
				Ip = hostIp,
			};

			//todo map more uptime etc
			return host;
		}

		private static long GetSysLogSeverity(LogLevel logLevel)
		{
			if (logLevel == LogLevel.Trace || logLevel == LogLevel.Debug)
				return 7;
			else if (logLevel == LogLevel.Info)
				return 6;
			else if (logLevel == LogLevel.Warn)
				return 4;
			else if (logLevel == LogLevel.Error)
				return 3;
			else
				return 2;   // LogLevel.Fatal
		}

		private static void PopulatePropertyBag(IDictionary<string, object> propertyBag, string key, object valueObj)
		{
			if (string.IsNullOrEmpty(key))
				return;

			if (propertyBag.ContainsKey(key))
			{
				if (string.Equals(value, propertyBag[key], StringComparison.Ordinal))
				{
					return;
				}

				key += "_1";
			}

			propertyBag.Add(key, value);
		}
	}
}

@codebrain
Copy link
Contributor Author

Many thanks for you insight here @snakefoot. I have updated the final layout (https://github.com/elastic/ecs-dotnet/blob/adb5c52692e3ff0975c12af7dad00d5d57696391/src/Elastic.CommonSchema.NLog/EcsLayout.cs) in a format similar to how you suggested. The tests seem happy, so I am going to move this to review by another member of the team.

@codebrain codebrain marked this pull request as ready for review February 19, 2020 06:45
@codebrain codebrain requested a review from Mpdreamz February 19, 2020 06:46
@codebrain codebrain mentioned this pull request Feb 19, 2020
@snakefoot
Copy link
Contributor

@codebrain Happy to help. I guess if it lives up to your standards, then I might suggest adding support for IncludeMldc-property to handle MLDC. Will make an example soon.

@snakefoot
Copy link
Contributor

snakefoot commented Feb 19, 2020

Btw. it is important to add these attributes:

[Layout("EcsLayout")]
[ThreadSafe]
[ThreadAgnostic]

This tells NLog that the Layout has been implemented properly, and concurrency is allowed:

using NLog.Config;

[Layout("EcsLayout")]
[ThreadSafe]
[ThreadAgnostic]
public class EcsLayout : Layout
{
        private readonly Layout _disableThreadAgnostic = "${threadid:cached=true}";

        /// <summary>
        /// Special hack that allows one to dynamically disable disable <see cref="ThreadAgnosticAttribute"/> to ensure correct async context capture when necessary
        /// </summary>
        public Layout DisableThreadAgnostic => IncludeMdlc ? _disableThreadAgnostic : null;

        public bool IncludeMdlc { get; set; }

        private IDictionary<string, object> GetMetadata(LogEventInfo e)
	{
	   if ((!IncludeAllProperties || !e.HasProperties) && MetaData?.Count == 0 && !IncludeMdlc)
		return null;

	  var metaData = new Dictionary<string, object>();

	  if (IncludeAllProperties && e.HasProperties)
	  {
		foreach (var prop in e.Properties)
			Populate(metaData, prop.Key?.ToString(), prop.Value);
	  }

	  if  (IncludeMdlc)
	  {
              foreach (string mdlcKey in NLog.MappedDiagnosticsLogicalContext.GetNames())
              {
                    if (string.IsNullOrEmpty(mdlcKey))
                        continue;

                    object propertyValue = MappedDiagnosticsLogicalContext.GetObject(key);
                    Populate(metaData, mdlcKey, propertyValue);
                }
	  }

	  if (MetaData?.Count > 0)
	  {
		for (var i = 0; i < MetaData.Count; ++i)
		{
			var value = MetaData[i].Layout?.Render(e);
			if (!string.IsNullOrEmpty(value) || MetaData[i].IncludeEmptyValue)
				Populate(metaData, MetaData[i].Name, value);
		}
	  }
	
          if (metaData.Count > 0)
		return metaData;

	  return null;
	}
}

@codebrain
Copy link
Contributor Author

Thanks @snakefoot, I have updated the code as suggested.

@codebrain codebrain changed the title NLog LayoutRenderer NLog Layout Feb 20, 2020
Copy link
Contributor

@russcam russcam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've left a few comments.

As discussed on our video call, I think it'd be good to have tests the NLog layout in conjunction with the APM agent NLog layout, as I suspect this might be a common usage.

@codebrain
Copy link
Contributor Author

cla/check

Copy link
Contributor

@russcam russcam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, left a small comment

@codebrain codebrain merged commit 1fe8dfa into master Feb 26, 2020
@codebrain codebrain deleted the feature/nlog-layoutrenderer branch February 26, 2020 04:28
@codebrain
Copy link
Contributor Author

I have now merged this in @snakefoot. Thank you for your input on this feature!

@snakefoot
Copy link
Contributor

snakefoot commented Mar 2, 2020

Maybe try moving code used by both Serilog and NLog into the Common-project so they are in sync.

Forexample Serilog CatchErrors includes StackTrace for inner-exceptions But NLog CatchError does not (At the same time you can optimize Serilog to not allocate unnecessary Exception-List)

Btw. since it is not possible to serialize directly into the StringBuilder, then you can simplify this method:

		protected override void RenderFormattedMessage(LogEventInfo logEventInfo, StringBuilder target)
                {
                        // blah blah
			var output = ecsEvent.Serialize();
                        target.Append(output);
                }

Into this:

		protected override string GetFormattedMessage(LogEventInfo logEvent)
		{
                        // blah blah
			var output = ecsEvent.Serialize();
                        return output;
		}

And remove the existing GetFormattedMessage

You should change this method:

		private static Log GetLog(LogEventInfo logEventInfo)
		{
			var log = new Log
			{
				Level = logEventInfo.Level.ToString(),
				Logger = SpecialKeys.DefaultLogger,
				Original = logEventInfo.Message
			};

			return log;
		}

Into this (Use logEventInfo.Logger instead of SpecialKeys.DefaultLogger):

		private static Log GetLog(LogEventInfo logEventInfo)
		{
			var log = new Log
			{
				Level = logEventInfo.Level.ToString(),
				Logger = logEventInfo.Logger,
				Original = logEventInfo.Message
			};

			return log;
		}

This will match the use of sourceContext for Serilog.

@codebrain
Copy link
Contributor Author

Thanks, I will raise this as a ticket so we can track it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants