Improvements/logging (#452)

* Improvements to logging system.
* Log level.
* Log level adjusted.

backend/src/Squidex.Infrastructure/Commands/LogCommandMiddleware.cs

@@ -28,7 +28,7 @@ namespace Squidex.Infrastructure.Commands
 
             try
             {
-                log.LogInformation(logContext, (ctx, w) => w
+                log.LogDebug(logContext, (ctx, w) => w
                     .WriteProperty("action", "HandleCommand.")
                     .WriteProperty("actionId", ctx.id)
                     .WriteProperty("status", "Started")

backend/src/Squidex.Infrastructure/EventSourcing/Grains/EventConsumerGrain.cs

@@ -203,13 +203,13 @@ namespace Squidex.Infrastructure.EventSourcing.Grains
         {
             var logContext = (actionId: Guid.NewGuid().ToString(), consumer: eventConsumer.Name);
 
-            log.LogInformation(logContext, (ctx, w) => w
+            log.LogDebug(logContext, (ctx, w) => w
                 .WriteProperty("action", "EventConsumerReset")
                 .WriteProperty("actionId", ctx.actionId)
                 .WriteProperty("status", "Started")
                 .WriteProperty("eventConsumer", ctx.consumer));
 
-            using (log.MeasureTrace(logContext, (ctx, w) => w
+            using (log.MeasureInformation(logContext, (ctx, w) => w
                 .WriteProperty("action", "EventConsumerReset")
                 .WriteProperty("actionId", ctx.actionId)
                 .WriteProperty("status", "Completed")
@@ -226,7 +226,7 @@ namespace Squidex.Infrastructure.EventSourcing.Grains
 
             var logContext = (eventId, eventType, consumer: eventConsumer.Name);
 
-            log.LogInformation(logContext, (ctx, w) => w
+            log.LogDebug(logContext, (ctx, w) => w
                 .WriteProperty("action", "HandleEvent")
                 .WriteProperty("actionId", ctx.eventId)
                 .WriteProperty("status", "Started")
@@ -234,7 +234,7 @@ namespace Squidex.Infrastructure.EventSourcing.Grains
                 .WriteProperty("eventType", ctx.eventType)
                 .WriteProperty("eventConsumer", ctx.consumer));
 
-            using (log.MeasureTrace(logContext, (ctx, w) => w
+            using (log.MeasureInformation(logContext, (ctx, w) => w
                 .WriteProperty("action", "HandleEvent")
                 .WriteProperty("actionId", ctx.eventId)
                 .WriteProperty("status", "Completed")

backend/src/Squidex.Infrastructure/Log/SemanticLog.cs

@@ -8,6 +8,7 @@
 using System;
 using System.Collections.Generic;
 using System.Linq;
+using Microsoft.Extensions.Options;
 
 namespace Squidex.Infrastructure.Log
 {
@@ -15,19 +16,23 @@ namespace Squidex.Infrastructure.Log
     {
         private readonly ILogChannel[] channels;
         private readonly ILogAppender[] appenders;
+        private readonly IOptions<SemanticLogOptions> options;
         private readonly IObjectWriterFactory writerFactory;
 
         public SemanticLog(
+            IOptions<SemanticLogOptions> options,
             IEnumerable<ILogChannel> channels,
             IEnumerable<ILogAppender> appenders,
             IObjectWriterFactory writerFactory)
         {
+            Guard.NotNull(options);
             Guard.NotNull(channels);
             Guard.NotNull(appenders);
             Guard.NotNull(writerFactory);
 
             this.channels = channels.ToArray();
             this.appenders = appenders.ToArray();
+            this.options = options;
             this.writerFactory = writerFactory;
         }
 
@@ -35,6 +40,11 @@ namespace Squidex.Infrastructure.Log
         {
             Guard.NotNull(action);
 
+            if (logLevel < options.Value.Level)
+            {
+                return;
+            }
+
             var formattedText = FormatText(logLevel, context, action);
 
             LogFormattedText(logLevel, formattedText);
@@ -92,7 +102,7 @@ namespace Squidex.Infrastructure.Log
 
         public ISemanticLog CreateScope(Action<IObjectWriter> objectWriter)
         {
-            return new SemanticLog(channels, appenders.Union(new ILogAppender[] { new ConstantsLogWriter(objectWriter) }).ToArray(), writerFactory);
+            return new SemanticLog(options, channels, appenders.Union(new ILogAppender[] { new ConstantsLogWriter(objectWriter) }).ToArray(), writerFactory);
         }
     }
 }

backend/src/Squidex.Infrastructure/Log/SemanticLogOptions.cs

@@ -0,0 +1,14 @@
+// ==========================================================================
+//  Squidex Headless CMS
+// ==========================================================================
+//  Copyright (c) Squidex UG (haftungsbeschraenkt)
+//  All rights reserved. Licensed under the MIT license.
+// ==========================================================================
+
+namespace Squidex.Infrastructure.Log
+{
+    public sealed class SemanticLogOptions
+    {
+        public SemanticLogLevel Level { get; set; } = SemanticLogLevel.Information;
+    }
+}

backend/src/Squidex.Web/Pipeline/RequestLogOptions.cs

@@ -0,0 +1,16 @@
+// ==========================================================================
+//  Squidex Headless CMS
+// ==========================================================================
+//  Copyright (c) Squidex UG (haftungsbeschraenkt)
+//  All rights reserved. Licensed under the MIT license.
+// ==========================================================================
+
+namespace Squidex.Web.Pipeline
+{
+    public sealed class RequestLogOptions
+    {
+        public bool LogRequest { get; set; }
+
+        public bool LogProfiler { get; set; }
+    }
+}

backend/src/Squidex.Web/Pipeline/RequestLogPerformanceMiddleware.cs

@@ -7,6 +7,7 @@
 
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Options;
 using Squidex.Infrastructure;
 using Squidex.Infrastructure.Log;
 using Squidex.Infrastructure.Security;
@@ -15,10 +16,13 @@ namespace Squidex.Web.Pipeline
 {
     public sealed class RequestLogPerformanceMiddleware : IMiddleware
     {
+        private readonly RequestLogOptions options;
         private readonly ISemanticLog log;
 
-        public RequestLogPerformanceMiddleware(ISemanticLog log)
+        public RequestLogPerformanceMiddleware(IOptions<RequestLogOptions> options, ISemanticLog log)
         {
+            this.options = options.Value;
+
             this.log = log;
         }
 
@@ -36,13 +40,19 @@ namespace Squidex.Web.Pipeline
                 {
                     var elapsedMs = watch.Stop();
 
-                    log.LogInformation((elapsedMs, context), (ctx, w) =>
+                    if (options.LogRequest)
                     {
-                        Profiler.Session?.Write(w);
+                        log.LogInformation((elapsedMs, context), (ctx, w) =>
+                        {
+                            if (options.LogProfiler)
+                            {
+                                Profiler.Session?.Write(w);
+                            }
 
-                        w.WriteObject("filters", ctx.context, LogFilters);
-                        w.WriteProperty("elapsedRequestMs", ctx.elapsedMs);
-                    });
+                            w.WriteObject("filters", ctx.context, LogFilters);
+                            w.WriteProperty("elapsedRequestMs", ctx.elapsedMs);
+                        });
+                    }
                 }
             }
         }

backend/src/Squidex/Config/Domain/LoggingServices.cs

@@ -32,6 +32,12 @@ namespace Squidex.Config.Domain
 
         private static void AddServices(this IServiceCollection services, IConfiguration config)
         {
+            services.Configure<RequestLogOptions>(
+                config.GetSection("logging"));
+
+            services.Configure<SemanticLogOptions>(
+                config.GetSection("logging"));
+
             if (config.GetValue<bool>("logging:human"))
             {
                 services.AddSingletonAs(_ => JsonLogWriterFactory.Readable())

backend/src/Squidex/appsettings.json

@@ -225,6 +225,12 @@
   },
 
   "logging": {
+    /*
+     * The log level.
+     *
+     * Trace, Debug, Information, Warning, Error, Fatal
+     */
+    "level": "Information",
     /*
      * Setting the flag to true, enables well formatteds json logs.
      */
@@ -232,7 +238,15 @@
     /*
      * Set to true, to use colors.
      */
-    "colors": true
+    "colors": true,
+    /*
+     * Set to false to disable logging of http requests.
+     */
+    "logRequests": true,
+    /*
+     * Set to true to enable logging of profiler information.
+     */
+    "logProfiler": false
   },
 
   "assetStore": {

backend/tests/Squidex.Infrastructure.Tests/Commands/LogCommandMiddlewareTests.cs

@@ -24,13 +24,10 @@ namespace Squidex.Infrastructure.Commands
 
         private sealed class MyLog : ISemanticLog
         {
-            public int LogCount { get; private set; }
-
             public Dictionary<SemanticLogLevel, int> LogLevels { get; } = new Dictionary<SemanticLogLevel, int>();
 
             public void Log<T>(SemanticLogLevel logLevel, T context, Action<T, IObjectWriter> action)
             {
-                LogCount++;
                 LogLevels[logLevel] = LogLevels.GetOrDefault(logLevel) + 1;
             }
 
@@ -57,8 +54,11 @@ namespace Squidex.Infrastructure.Commands
                 return TaskHelper.Done;
             });
 
-            Assert.Equal(3, log.LogCount);
-            Assert.Equal(3, log.LogLevels[SemanticLogLevel.Information]);
+            Assert.Equal(log.LogLevels, new Dictionary<SemanticLogLevel, int>
+            {
+                [SemanticLogLevel.Debug] = 1,
+                [SemanticLogLevel.Information] = 2
+            });
         }
 
         [Fact]
@@ -71,9 +71,12 @@ namespace Squidex.Infrastructure.Commands
                 await sut.HandleAsync(context, () => throw new InvalidOperationException());
             });
 
-            Assert.Equal(3, log.LogCount);
-            Assert.Equal(2, log.LogLevels[SemanticLogLevel.Information]);
-            Assert.Equal(1, log.LogLevels[SemanticLogLevel.Error]);
+            Assert.Equal(log.LogLevels, new Dictionary<SemanticLogLevel, int>
+            {
+                [SemanticLogLevel.Debug] = 1,
+                [SemanticLogLevel.Information] = 1,
+                [SemanticLogLevel.Error] = 1,
+            });
         }
 
         [Fact]
@@ -83,9 +86,12 @@ namespace Squidex.Infrastructure.Commands
 
             await sut.HandleAsync(context, () => TaskHelper.Done);
 
-            Assert.Equal(4, log.LogCount);
-            Assert.Equal(3, log.LogLevels[SemanticLogLevel.Information]);
-            Assert.Equal(1, log.LogLevels[SemanticLogLevel.Fatal]);
+            Assert.Equal(log.LogLevels, new Dictionary<SemanticLogLevel, int>
+            {
+                [SemanticLogLevel.Debug] = 1,
+                [SemanticLogLevel.Information] = 2,
+                [SemanticLogLevel.Fatal] = 1,
+            });
         }
     }
 }

backend/tests/Squidex.Infrastructure.Tests/Log/SemanticLogAdapterTests.cs

@@ -10,6 +10,7 @@ using System.Collections.Generic;
 using FakeItEasy;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Logging.Abstractions;
+using Microsoft.Extensions.Options;
 using Squidex.Infrastructure.Log.Adapter;
 using Xunit;
 
@@ -17,6 +18,7 @@ namespace Squidex.Infrastructure.Log
 {
     public class SemanticLogAdapterTests
     {
+        private readonly IOptions<SemanticLogOptions> options = Options.Create(new SemanticLogOptions());
         private readonly List<ILogChannel> channels = new List<ILogChannel>();
         private readonly Lazy<SemanticLog> log;
         private readonly ILogChannel channel = A.Fake<ILogChannel>();
@@ -30,6 +32,8 @@ namespace Squidex.Infrastructure.Log
 
         public SemanticLogAdapterTests()
         {
+            options.Value.Level = SemanticLogLevel.Trace;
+
             channels.Add(channel);
 
             A.CallTo(() => channel.Log(A<SemanticLogLevel>.Ignored, A<string>.Ignored))
@@ -38,7 +42,7 @@ namespace Squidex.Infrastructure.Log
                     output = message;
                 });
 
-            log = new Lazy<SemanticLog>(() => new SemanticLog(channels, new List<ILogAppender>(), JsonLogWriterFactory.Default()));
+            log = new Lazy<SemanticLog>(() => new SemanticLog(options, channels, new List<ILogAppender>(), JsonLogWriterFactory.Default()));
 
             sut = SemanticLogLoggerProvider.ForTesting(log.Value);
         }

backend/tests/Squidex.Infrastructure.Tests/Log/SemanticLogTests.cs

@@ -10,6 +10,7 @@ using System.Collections.Generic;
 using System.Linq;
 using FakeItEasy;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
 using NodaTime;
 using Squidex.Infrastructure.Log.Adapter;
 using Xunit;
@@ -20,6 +21,7 @@ namespace Squidex.Infrastructure.Log
     {
         private readonly List<ILogAppender> appenders = new List<ILogAppender>();
         private readonly List<ILogChannel> channels = new List<ILogChannel>();
+        private readonly IOptions<SemanticLogOptions> options = Options.Create(new SemanticLogOptions());
         private readonly Lazy<SemanticLog> log;
         private readonly ILogChannel channel = A.Fake<ILogChannel>();
         private string output = string.Empty;
@@ -31,6 +33,8 @@ namespace Squidex.Infrastructure.Log
 
         public SemanticLogTests()
         {
+            options.Value.Level = SemanticLogLevel.Trace;
+
             channels.Add(channel);
 
             A.CallTo(() => channel.Log(A<SemanticLogLevel>.Ignored, A<string>.Ignored))
@@ -39,7 +43,7 @@ namespace Squidex.Infrastructure.Log
                     output += message;
                 });
 
-            log = new Lazy<SemanticLog>(() => new SemanticLog(channels, appenders, JsonLogWriterFactory.Default()));
+            log = new Lazy<SemanticLog>(() => new SemanticLog(options, channels, appenders, JsonLogWriterFactory.Default()));
         }
 
         [Fact]
@@ -498,7 +502,7 @@ namespace Squidex.Infrastructure.Log
             A.CallTo(() => channel1.Log(A<SemanticLogLevel>.Ignored, A<string>.Ignored)).Throws(exception1);
             A.CallTo(() => channel2.Log(A<SemanticLogLevel>.Ignored, A<string>.Ignored)).Throws(exception2);
 
-            var sut = new SemanticLog(new[] { channel1, channel2 }, Enumerable.Empty<ILogAppender>(), JsonLogWriterFactory.Default());
+            var sut = new SemanticLog(options, new[] { channel1, channel2 }, Enumerable.Empty<ILogAppender>(), JsonLogWriterFactory.Default());
 
             try
             {
@@ -513,6 +517,16 @@ namespace Squidex.Infrastructure.Log
             }
         }
 
+        [Fact]
+        public void Should_not_log_if_level_is_too_low()
+        {
+            options.Value.Level = SemanticLogLevel.Error;
+
+            Log.LogWarning(w => w.WriteProperty("Property", "Value"));
+
+            Assert.Equal(string.Empty, output);
+        }
+
         private static string LogTest(Action<IObjectWriter> writer)
         {
             var sut = JsonLogWriterFactory.Default().Create();