Add syslog style log levels to IoT Edge logs (#942)

* Add severity to log messages

* Add comment

* Add comment

* Fix test changes

* Fix Logger test after refactor

edge-util/src/Microsoft.Azure.Devices.Edge.Util/Logger.cs

@@ -5,6 +5,7 @@ namespace Microsoft.Azure.Devices.Edge.Util
     using System.Collections.Generic;
     using Microsoft.Extensions.Logging;
     using Serilog;
+    using Serilog.Configuration;
     using Serilog.Core;
     using Serilog.Events;
 
@@ -23,7 +24,7 @@ public static class Logger
             { "fatal", LogEventLevel.Fatal }
         };
 
-        static readonly Lazy<ILoggerFactory> LoggerLazy = new Lazy<ILoggerFactory>(() => GetLoggerFactory(), true);
+        static readonly Lazy<ILoggerFactory> LoggerLazy = new Lazy<ILoggerFactory>(GetLoggerFactory, true);
         static LogEventLevel logLevel = LogEventLevel.Information;
 
         public static ILoggerFactory Factory => LoggerLazy.Value;
@@ -38,28 +39,62 @@ public static void SetLogLevel(string level)
 
         static ILoggerFactory GetLoggerFactory()
         {
-            var levelSwitch = new LoggingLevelSwitch();
-            levelSwitch.MinimumLevel = logLevel;
-            Serilog.Core.Logger loggerConfig = new LoggerConfiguration()
+            string outputTemplate = logLevel > LogEventLevel.Debug
+                ? "<{Severity}> {Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] - {Message}{NewLine}{Exception}"
+                : "<{Severity}> {Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] [{SourceContext:1}] - {Message}{NewLine}{Exception}";
+
+            LoggerConfiguration ConsoleSinkMap(LoggerSinkConfiguration loggerSinkConfiguration)
+                => loggerSinkConfiguration.Console(outputTemplate: outputTemplate);
+
+            return GetLoggerFactory(logLevel, ConsoleSinkMap);
+        }
+
+        internal static ILoggerFactory GetLoggerFactory(LogEventLevel logEventLevel, Func<LoggerSinkConfiguration, LoggerConfiguration> loggerSink)
+        {
+            var levelSwitch = new LoggingLevelSwitch
+            {
+                MinimumLevel = logEventLevel
+            };
+
+            LoggerSinkConfiguration loggerSinkConfiguration = new LoggerConfiguration()
                 .MinimumLevel.ControlledBy(levelSwitch)
                 .Enrich.FromLogContext()
-                .WriteTo.Console(
-                    outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] - {Message}{NewLine}{Exception}").CreateLogger();
+                .Enrich.With(SeverityEnricher.Instance)
+                .WriteTo;
 
-            if (levelSwitch.MinimumLevel <= LogEventLevel.Debug)
-            {
-                // Overwrite with richer content if less then debug
-                loggerConfig = new LoggerConfiguration()
-                    .MinimumLevel.ControlledBy(levelSwitch)
-                    .Enrich.FromLogContext()
-                    .WriteTo.Console(
-                        outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] [{SourceContext:1}] - {Message}{NewLine}{Exception}").CreateLogger();
-            }
+            Serilog.Core.Logger loggerConfig = loggerSink(loggerSinkConfiguration).CreateLogger();
 
             ILoggerFactory factory = new LoggerFactory()
                 .AddSerilog(loggerConfig);
 
             return factory;
         }
+
+        // This maps the Edge log level to the severity level based on Syslog severity levels.
+        // https://en.wikipedia.org/wiki/Syslog#Severity_level
+        // This allows tools to parse the severity level from the log text and use it to enhance the log
+        // For example errors can show up as red
+        class SeverityEnricher : ILogEventEnricher
+        {
+            static readonly IDictionary<LogEventLevel, int> LogLevelSeverityMap = new Dictionary<LogEventLevel, int>
+            {
+                [LogEventLevel.Fatal] = 0,
+                [LogEventLevel.Error] = 3,
+                [LogEventLevel.Warning] = 4,
+                [LogEventLevel.Information] = 6,
+                [LogEventLevel.Debug] = 7,
+                [LogEventLevel.Verbose] = 7
+            };
+
+            SeverityEnricher()
+            {
+            }
+
+            public static SeverityEnricher Instance => new SeverityEnricher();
+
+            public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) =>
+                logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
+                    "Severity", LogLevelSeverityMap[logEvent.Level]));
+        }
     }
 }

edge-util/test/Microsoft.Azure.Devices.Edge.Util.Test/LoggerTest.cs

@@ -0,0 +1,60 @@
+// Copyright (c) Microsoft. All rights reserved.
+namespace Microsoft.Azure.Devices.Edge.Util.Test
+{
+    using System.Collections.Generic;
+    using Microsoft.Azure.Devices.Edge.Util.Test.Common;
+    using Microsoft.Extensions.Logging;
+    using Serilog;
+    using Serilog.Configuration;
+    using Serilog.Core;
+    using Serilog.Events;
+    using Xunit;
+    using ILogger = Microsoft.Extensions.Logging.ILogger;
+    using Logger = Microsoft.Azure.Devices.Edge.Util.Logger;
+
+    [Unit]
+    public class LoggerTest
+    {
+        [Fact]
+        public void SeverityTest()
+        {
+            var testSink = new TestSink();
+
+            LoggerConfiguration TestSinkMap(LoggerSinkConfiguration loggerSinkConfiguration)
+                => loggerSinkConfiguration.Sink(testSink);
+
+            ILogger logger = Logger.GetLoggerFactory(LogEventLevel.Debug, TestSinkMap).CreateLogger("test");
+            Assert.NotNull(logger);
+
+            logger.LogInformation("Test message");
+            List<LogEvent> emittedEvents = testSink.GetEmittedEvents();
+            Assert.Equal("6", emittedEvents[0].Properties["Severity"].ToString());
+            testSink.Reset();
+
+            logger.LogDebug("Test message");
+            emittedEvents = testSink.GetEmittedEvents();
+            Assert.Equal("7", emittedEvents[0].Properties["Severity"].ToString());
+            testSink.Reset();
+
+            logger.LogWarning("Test message");
+            emittedEvents = testSink.GetEmittedEvents();
+            Assert.Equal("4", emittedEvents[0].Properties["Severity"].ToString());
+            testSink.Reset();
+
+            logger.LogError("Test message");
+            emittedEvents = testSink.GetEmittedEvents();
+            Assert.Equal("3", emittedEvents[0].Properties["Severity"].ToString());
+        }
+
+        class TestSink : ILogEventSink
+        {
+            List<LogEvent> emittedEvents = new List<LogEvent>();
+
+            public void Emit(LogEvent logEvent) => this.emittedEvents.Add(logEvent);
+
+            public List<LogEvent> GetEmittedEvents() => this.emittedEvents;
+
+            public void Reset() => this.emittedEvents = new List<LogEvent>();
+        }
+    }
+}