#1744 Avoid calls to 'Logger.Log' if LogLevel not enabled in appsetti…

…ngs.json (#1745)

* changing string parameter for IOcelotLogger function to Func<string>, modifying asp dot net logger, only one main method and verifying if LogLevel is enabled. If log level isn't enabled, then return.

    pick 847dac7 changing string parameter for IOcelotLogger function to Func<string>, modifying asp dot net logger, only one main method and verifying if LogLevel is enabled. If log level isn't enabled, then return.
    pick d7a8397 adding back the logger methods with string as parameter, avoiding calling the factory when plain string are used.
    pick d413201 simplify method calls

* adding back the logger methods with string as parameter, avoiding calling the factory when plain string are used.

* simplify method calls

* adding unit test case, If minimum log level not set then no logs are written

* adding logging benchmark

* code cleanup in steps and naming issues fixes

   pick c4f6dc9 adding loglevel acceptance tests, verifying that the logs are returned according to the minimum log level set in appsettings
   pick 478f139 enhanced unit tests, verifying 1) that the log method is only called when log level enabled 2) that the string function is only invoked when log level enabled

* adding loglevel acceptance tests, verifying that the logs are returned according to the minimum log level set in appsettings

* enhanced unit tests, verifying 1) that the log method is only called when log level enabled 2) that the string function is only invoked when log level enabled

* weird issue with the merge.

* adding comment

* Update src/Ocelot/ServiceDiscovery/ServiceDiscoveryProviderFactory.cs

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

* Update src/Ocelot/Claims/Middleware/ClaimsToClaimsMiddleware.cs

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

* Update src/Ocelot/Configuration/Repository/FileConfigurationPoller.cs

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

* Update src/Ocelot/DownstreamRouteFinder/Finder/DownstreamRouteProviderFactory.cs

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

* Update src/Ocelot/Logging/AspDotNetLogger.cs

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

* Update test/Ocelot.AcceptanceTests/LogLevelTests.cs

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

* Update src/Ocelot/Configuration/Repository/FileConfigurationPoller.cs

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

* As mentioned, using OcelotLogger instead of AspDotNeLogger as default logger name

* Some code refactoring and usage of factories in LogLevelTests

* Update src/Ocelot/Claims/Middleware/ClaimsToClaimsMiddleware.cs

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

* using overrided method WriteLog for strings, some changes as requested,

* code changes after review 2

    pick ad0e060 Update test/Ocelot.UnitTests/Middleware/OcelotPiplineBuilderTests.cs

* checking test cases

* adding ms logger benchmarks with console provider. Unfortunately, benchmark.net doesn't support "quiet" mode yet.

* 2 small adjustments

* Adding multi targets support for serilog

* Fix warnings

* Review new logger

* Fix unit tests

* The last change but not least

* Update logging.rst: Add draft

* Update logging.rst: Add RequestId section

* Update logging.rst: "Best Practices" section

* Update logging.rst: "Top Logging Performance?" subsection

* Update logging.rst: Rewrite "Request ID" section

* Update requestid.rst: Review and up to date

* Update logging.rst: "Run Benchmarks" section

---------

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>

docs/features/logging.rst

@@ -2,23 +2,154 @@ Logging
 =======
 
 Ocelot uses the standard logging interfaces ``ILoggerFactory`` and ``ILogger<T>`` at the moment.
-This is encapsulated in ``IOcelotLogger`` and ``IOcelotLoggerFactory`` with an implementation for the standard `ASP.NET Core logging <https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/>`_ stuff at the moment.
-This is because Ocelot adds some extra info to the logs such as **request ID** if it is configured.
+This is encapsulated in ``IOcelotLogger`` and ``IOcelotLoggerFactory`` with the implementation for the standard `ASP.NET Core logging <https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/>`_ stuff at the moment.
+This is because Ocelot adds some extra info to the logs such as **RequestId** if it is configured.
 
 There is a global `error handler middleware <https://github.com/search?q=repo%3AThreeMammals%2FOcelot%20ExceptionHandlerMiddleware&type=code>`_ that should catch any exceptions thrown and log them as errors.
 
-Finally, if logging is set to **Trace** level, Ocelot will log starting, finishing and any middlewares that throw an exception which can be quite useful.
+Finally, if logging is set to ``Trace`` level, Ocelot will log starting, finishing and any middlewares that throw an exception which can be quite useful.
+
+Request ID
+----------
 
 The reason for not just using `bog standard <https://notoneoffbritishisms.com/2015/03/27/bog-standard/>`_ framework logging is that
-we could not work out how to override the request id that get's logged when setting **IncludeScopes** to ``true`` for logging settings.
+we could not work out how to override the **RequestId** that get's logged when setting **IncludeScopes** to ``true`` for logging settings.
 Nicely onto the next feature.
 
+Every log record has these 2 properties:
+
+* **RequestId** represents ID of the current request as plain string, for example ``0HMVD33IIJRFR:00000001``
+* **PreviousRequestId** represents ID of the previous request
+
+As an ``IOcelotLogger`` interface object being injected to constructors of service classes, current default Ocelot logger (``OcelotLogger`` class) reads these 2 properties from the ``IRequestScopedDataRepository`` interface object.
+Find out more about these properties and other details on the *Request ID* logging feature in the  :doc:`../features/requestid` chapter.
+
 Warning
 -------
 
-If you are logging to `Console <https://learn.microsoft.com/en-us/dotnet/api/system.console>`_, you will get terrible performance.
-The team has had so many issues about performance issues with Ocelot and it is always logging level **Debug**, logging to `Console <https://learn.microsoft.com/en-us/dotnet/api/system.console>`_.
+If you are logging to MS `Console <https://learn.microsoft.com/en-us/dotnet/api/system.console>`_, you will get terrible performance.
+The team has had so many issues about performance issues with Ocelot and it is always logging level ``Debug``, logging to `Console <https://learn.microsoft.com/en-us/dotnet/api/system.console>`_.
 
 * **Warning!** Make sure you are logging to something proper in production environment!
-* Use **Error** and **Critical** levels in production environment!
-* Use **Warning** level in testing environment!
+* Use ``Error`` and ``Critical`` levels in production environment!
+* Use ``Warning`` level in testing & staging environments!
+
+These and other recommendations are below in the `Best Practices <#best-practices>`_ section.
+
+Best Practices
+--------------
+
+    | Microsoft Learn сomplete reference: `Logging in .NET Core and ASP.NET Core <https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/>`_
+
+Our recommendations to gain Ocelot best logging are the following.
+
+First
+^^^^^
+
+Ensure minimum level while `Configure logging <https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/#configure-logging>`_.
+The minimum log level is set in the application's ``appsettings.json`` file. This level is defined in the **Logging** section, for example:
+
+.. code-block:: json
+
+  {
+    "Logging": {
+      "LogLevel": {
+        "Default": "Information",
+        "Microsoft.AspNetCore": "Warning"
+      }
+    }
+  }
+
+Whether using `Serilog <https://serilog.net/>`_ or the standard Microsoft providers, the logging configuration will be retrieved from this section.
+
+.. code-block:: csharp
+
+    .ConfigureAppConfiguration((_, config) =>
+    {
+        config.AddJsonFile($"appsettings.{env.EnvironmentName}.json", false, false);
+        // ...
+    })
+
+However, there is one thing to be aware of. It is possible to use the ``SetMinimumLevel()`` method to define the minimum logging level.
+Be careful and make sure you set the log level in one place only, like:
+
+.. code-block:: csharp
+
+    ConfigureLogging(logging =>
+    {
+        logging.ClearProviders();
+        logging.SetMinimumLevel(minLogLevel);
+        logging.AddConsole(); // MS Console for Development and/or Testing environments only
+    })
+
+Please also use the ``ClearProviders()`` method, so that only the providers you wish to use are taken into account, as in the example above, the console.
+
+Second
+^^^^^^
+
+Ensure proper usage of minimum logging level for each environment: development, testing, production, etc.
+So, once again, read important notes of the `Warning <#warning>`_ section! 
+
+Third
+^^^^^
+
+Ocelot's logging has been improved in `22.0 <https://github.com/ThreeMammals/Ocelot/releases/tag/22.0.0>`_ version:
+it is now possible to use a factory method for message strings that will only be executed if the minimum log level allows it.
+
+For example, let's take a message containing information about several variables that should only be generated if the minimum log level is ``Debug``.
+If the minimum log level is ``Warning`` then the string is never generated.
+
+Therefore, when the string contains dynamic information aka ``string.Format``, or string value is generated by `string interpolation <https://learn.microsoft.com/en-us/dotnet/csharp/tutorials/string-interpolation>`_ expression,
+it is recommended to call the log method using anonymous delegate via an ``=>`` expression function:
+
+.. code-block:: csharp
+
+    Logger.LogDebug(() => $"downstream templates are {string.Join(", ", response.Data.Route.DownstreamRoute.Select(r => r.DownstreamPathTemplate.Value))}");
+
+otherwise a constant string is sufficient
+
+.. code-block:: csharp
+
+    Logger.LogDebug("My const string");
+
+Performance Review
+------------------
+
+Ocelot's logging performance has been improved in version `22.0 <https://github.com/ThreeMammals/Ocelot/releases/tag/22.0.0>`__ (see PR `1745 <https://github.com/ThreeMammals/Ocelot/pull/1745>`_).
+These changes were requested as part of issue `1744 <https://github.com/ThreeMammals/Ocelot/issues/1744>`_ after team's `discussion <https://github.com/ThreeMammals/Ocelot/discussions/1736>`_.
+
+Top Logging Performance?
+^^^^^^^^^^^^^^^^^^^^^^^^
+
+Here is a quick recipe for your Production environment!
+You need to ensure the minimal level is ``Critical`` or ``None``. Nothing more!
+For sure, having top logging performance means having less log records written by logging provider. So, logs should be pretty empty.
+
+Anyway, during the first time after a version release to production, we recommend to watch the system and current version app behavior by specifying ``Error`` minimum level.
+If release engineer will ensure stability of the version in production then minimum level can be increased to ``Critical`` or ``None`` to gain top performance.
+Technically this will switch off the logging feature at all.
+
+Run Benchmarks
+^^^^^^^^^^^^^^
+
+We have 2 types of benchmarks currently
+
+* ``SerilogBenchmarks`` with Serilog logging to a file. See ``ConfigureLogging`` method with ``logging.AddSerilog(_logger);``
+* ``MsLoggerBenchmarks`` with MS default logging to MS Console. See ``ConfigureLogging`` method with ``logging.AddConsole();``
+
+Benchmark results largely depend on the environment and hardware on which they run.
+We are pleased to invite you to run Logging benchmarks on your machine by the following instructions below.
+
+1. Open PowerShell or Command Prompt console
+2. Build Ocelot solution in Release mode: ``dotnet build --configuration Release``
+3. Go to ``test\Ocelot.Benchmarks\bin\Release\`` folder.
+4. Choose .NET version changing the folder, for example to ``net8.0``
+5. Run **Ocelot.Benchmarks.exe**: ``.\Ocelot.Benchmarks.exe``
+6. Run ``SerilogBenchmarks`` or ``MsLoggerBenchmarks`` by pressing appropriate number of a benchmark: ``5`` or ``6``, + Enter
+7. Wait for 3+ minutes to complete benchmark, and get final results.
+8. Read and analize your benchmark session results.
+
+Indicators
+^^^^^^^^^^
+
+``To be developed...``

docs/features/requestid.rst

@@ -1,13 +1,13 @@
 Request ID
 ==========
 
-     aka **Correlation ID**
+     aka **Correlation ID** or `HttpContext.TraceIdentifier <https://learn.microsoft.com/en-us/dotnet/api/microsoft.aspnetcore.http.httpcontext.traceidentifier>`_
 
 Ocelot supports a client sending a *request ID* in the form of a header.
-If set, Ocelot will use the **requestId** for logging as soon as it becomes available in the middleware pipeline. 
-Ocelot will also forward the *request ID* with the specified header to the downstream service.
+If set, Ocelot will use the **RequestId** for logging as soon as it becomes available in the middleware pipeline. 
+Ocelot will also forward the *RequestId* with the specified header to the downstream service.
 
-You can still get the ASP.NET Core *request ID* in the logs if you set **IncludeScopes** ``true`` in your logging config.
+You can still get the ASP.NET Core *Request ID* in the logs if you set **IncludeScopes** ``true`` in your logging config.
 
 In order to use the *Request ID* feature you have two options.
 
@@ -67,3 +67,24 @@ Below is an example of the logging when set at ``Debug`` level for a normal requ
           requestId: 1234, previousRequestId: asdf, message: no pipeline errors, setting and returning completed response,
     dbug: Ocelot.Errors.Middleware.ExceptionHandlerMiddleware[0]
           requestId: 1234, previousRequestId: asdf, message: ocelot pipeline finished,
+
+And more practical example from secret production environment in Switzerland:
+
+.. code-block:: text
+
+    warn: Ocelot.DownstreamRouteFinder.Middleware.DownstreamRouteFinderMiddleware[0]
+          requestId: 0HMVD33IIJRFR:00000001, previousRequestId: no previous request id, message: DownstreamRouteFinderMiddleware setting pipeline errors. IDownstreamRouteFinder returned Error Code: UnableToFindDownstreamRouteError Message: Failed to match Route configuration for upstream path: /, verb: GET.
+    warn: Ocelot.Responder.Middleware.ResponderMiddleware[0]
+          requestId: 0HMVD33IIJRFR:00000001, previousRequestId: no previous request id, message: Error Code: UnableToFindDownstreamRouteError Message: Failed to match Route configuration for upstream path: /, verb: GET. errors found in ResponderMiddleware. Setting error response for request path:/, request method: GET
+
+Curious?
+--------
+
+*Request ID* is a part of big :doc:`../features/logging` feature.
+
+Every log record has these 2 properties:
+
+* **RequestId** represents ID of the current request as plain string, for example ``0HMVD33IIJRFR:00000001``
+* **PreviousRequestId** represents ID of the previous request
+
+As an ``IOcelotLogger`` interface object being injected to constructors of service classes, current default Ocelot logger (the ``OcelotLogger`` class) reads these 2 properties from the ``IRequestScopedDataRepository`` interface object.

src/Ocelot.Provider.Consul/Consul.cs

@@ -44,7 +44,7 @@ public async Task<List<Service>> GetAsync()
             else
             {
                 _logger.LogWarning(
-                    $"Unable to use service address: '{service.Address}' and port: {service.Port} as it is invalid for the service: '{service.Service}'. Address must contain host only e.g. 'localhost', and port must be greater than 0.");
+                    () => $"Unable to use service address: '{service.Address}' and port: {service.Port} as it is invalid for the service: '{service.Service}'. Address must contain host only e.g. 'localhost', and port must be greater than 0.");
             }
         }
 

src/Ocelot.Provider.Consul/PollConsul.cs

@@ -50,7 +50,7 @@ public Task<List<Service>> GetAsync()
 
             try
             {
-                _logger.LogInformation($"Retrieving new client information for service: {ServiceName}...");
+                _logger.LogInformation(() => $"Retrieving new client information for service: {ServiceName}...");
                 _services = _consulServiceDiscoveryProvider.GetAsync().Result;
                 return Task.FromResult(_services);
             }

src/Ocelot.Provider.Kubernetes/KubernetesServiceDiscoveryProvider.cs

@@ -30,7 +30,7 @@ public async Task<List<Service>> GetAsync()
         }
         else
         {
-            _logger.LogWarning($"namespace:{_kubeRegistryConfiguration.KubeNamespace}service:{_kubeRegistryConfiguration.KeyOfServiceInK8s} Unable to use ,it is invalid. Address must contain host only e.g. localhost and port must be greater than 0");
+            _logger.LogWarning(() => $"namespace:{_kubeRegistryConfiguration.KubeNamespace}service:{_kubeRegistryConfiguration.KeyOfServiceInK8s} Unable to use ,it is invalid. Address must contain host only e.g. localhost and port must be greater than 0");
         }
 
         return services;

src/Ocelot/Authentication/Middleware/AuthenticationMiddleware.cs

@@ -23,30 +23,30 @@ public async Task Invoke(HttpContext httpContext)
 
             if (httpContext.Request.Method.ToUpper() != "OPTIONS" && IsAuthenticatedRoute(downstreamRoute))
             {
-                Logger.LogInformation($"{httpContext.Request.Path} is an authenticated route. {MiddlewareName} checking if client is authenticated");
+                Logger.LogInformation(() => $"{httpContext.Request.Path} is an authenticated route. {MiddlewareName} checking if client is authenticated");
 
                 var result = await httpContext.AuthenticateAsync(downstreamRoute.AuthenticationOptions.AuthenticationProviderKey);
 
                 httpContext.User = result.Principal;
 
                 if (httpContext.User.Identity.IsAuthenticated)
                 {
-                    Logger.LogInformation($"Client has been authenticated for {httpContext.Request.Path}");
+                    Logger.LogInformation(() => $"Client has been authenticated for {httpContext.Request.Path}");
                     await _next.Invoke(httpContext);
                 }
                 else
                 {
                     var error = new UnauthenticatedError(
                         $"Request for authenticated route {httpContext.Request.Path} by {httpContext.User.Identity.Name} was unauthenticated");
 
-                    Logger.LogWarning($"Client has NOT been authenticated for {httpContext.Request.Path} and pipeline error set. {error}");
+                    Logger.LogWarning(() =>$"Client has NOT been authenticated for {httpContext.Request.Path} and pipeline error set. {error}");
 
                     httpContext.Items.SetError(error);
                 }
             }
             else
             {
-                Logger.LogInformation($"No authentication needed for {httpContext.Request.Path}");
+                Logger.LogInformation(() => $"No authentication needed for {httpContext.Request.Path}");
 
                 await _next.Invoke(httpContext);
             }

src/Ocelot/Authorization/Middleware/AuthorizationMiddleware.cs

@@ -62,27 +62,27 @@ public async Task Invoke(HttpContext httpContext)
 
                 if (authorized.IsError)
                 {
-                    Logger.LogWarning($"Error whilst authorizing {httpContext.User.Identity.Name}. Setting pipeline error");
+                    Logger.LogWarning(() => $"Error whilst authorizing {httpContext.User.Identity.Name}. Setting pipeline error");
 
                     httpContext.Items.UpsertErrors(authorized.Errors);
                     return;
                 }
 
                 if (IsAuthorized(authorized))
                 {
-                    Logger.LogInformation($"{httpContext.User.Identity.Name} has succesfully been authorized for {downstreamRoute.UpstreamPathTemplate.OriginalValue}.");
+                    Logger.LogInformation(() => $"{httpContext.User.Identity.Name} has succesfully been authorized for {downstreamRoute.UpstreamPathTemplate.OriginalValue}.");
                     await _next.Invoke(httpContext);
                 }
                 else
                 {
-                    Logger.LogWarning($"{httpContext.User.Identity.Name} is not authorized to access {downstreamRoute.UpstreamPathTemplate.OriginalValue}. Setting pipeline error");
+                    Logger.LogWarning(() => $"{httpContext.User.Identity.Name} is not authorized to access {downstreamRoute.UpstreamPathTemplate.OriginalValue}. Setting pipeline error");
 
                     httpContext.Items.SetError(new UnauthorizedError($"{httpContext.User.Identity.Name} is not authorized to access {downstreamRoute.UpstreamPathTemplate.OriginalValue}"));
                 }
             }
             else
             {
-                Logger.LogInformation($"{downstreamRoute.DownstreamPathTemplate.Value} route does not require user to be authorized");
+                Logger.LogInformation(() => $"{downstreamRoute.DownstreamPathTemplate.Value} route does not require user to be authorized");
                 await _next.Invoke(httpContext);
             }
         }

src/Ocelot/Cache/Middleware/OutputCacheMiddleware.cs

@@ -35,29 +35,29 @@ public async Task Invoke(HttpContext httpContext)
             var downstreamUrlKey = $"{downstreamRequest.Method}-{downstreamRequest.OriginalString}";
             var downStreamRequestCacheKey = await _cacheGenerator.GenerateRequestCacheKey(downstreamRequest, downstreamRoute);
 
-            Logger.LogDebug($"Started checking cache for the '{downstreamUrlKey}' key.");
+            Logger.LogDebug(() => $"Started checking cache for the '{downstreamUrlKey}' key.");
 
             var cached = _outputCache.Get(downStreamRequestCacheKey, downstreamRoute.CacheOptions.Region);
 
             if (cached != null)
             {
-                Logger.LogDebug($"Cache entry exists for the '{downstreamUrlKey}' key.");
+                Logger.LogDebug(() => $"Cache entry exists for the '{downstreamUrlKey}' key.");
 
                 var response = CreateHttpResponseMessage(cached);
                 SetHttpResponseMessageThisRequest(httpContext, response);
 
-                Logger.LogDebug($"Finished returning of cached response for the '{downstreamUrlKey}' key.");
+                Logger.LogDebug(() => $"Finished returning of cached response for the '{downstreamUrlKey}' key.");
 
                 return;
             }
 
-            Logger.LogDebug($"No response cached for the '{downstreamUrlKey}' key.");
+            Logger.LogDebug(() => $"No response cached for the '{downstreamUrlKey}' key.");
 
             await _next.Invoke(httpContext);
 
             if (httpContext.Items.Errors().Count > 0)
             {
-                Logger.LogDebug($"There was a pipeline error for the '{downstreamUrlKey}' key.");
+                Logger.LogDebug(() => $"There was a pipeline error for the '{downstreamUrlKey}' key.");
 
                 return;
             }
@@ -68,7 +68,7 @@ public async Task Invoke(HttpContext httpContext)
 
             _outputCache.Add(downStreamRequestCacheKey, cached, TimeSpan.FromSeconds(downstreamRoute.CacheOptions.TtlSeconds), downstreamRoute.CacheOptions.Region);
 
-            Logger.LogDebug($"Finished response added to cache for the '{downstreamUrlKey}' key.");
+            Logger.LogDebug(() => $"Finished response added to cache for the '{downstreamUrlKey}' key.");
         }
 
         private static void SetHttpResponseMessageThisRequest(HttpContext context,

src/Ocelot/Claims/Middleware/ClaimsToClaimsMiddleware.cs

@@ -1,6 +1,6 @@
-using Microsoft.AspNetCore.Http;
-using Ocelot.Logging;
-using Ocelot.Middleware;
+using Microsoft.AspNetCore.Http;
+using Ocelot.Logging;
+using Ocelot.Middleware;
 
 namespace Ocelot.Claims.Middleware
 {