Update middelware to use logging extension methods

src/Ocelot/Authentication/Middleware/AuthenticationMiddleware.cs

@@ -34,7 +34,7 @@ namespace Ocelot.Authentication.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogTrace($"entered {MiddlwareName}");
+            _logger.TraceMiddlewareEntry();
 
             if (IsAuthenticatedRoute(DownstreamRoute.ReRoute))
             {
@@ -46,6 +46,7 @@ namespace Ocelot.Authentication.Middleware
                 {
                     _logger.LogError($"Error getting authentication handler for {context.Request.Path}. {authenticationHandler.Errors.ToErrorString()}");
                     SetPipelineError(authenticationHandler.Errors);
+                    _logger.TraceMiddlewareCompleted();
                     return;
                 }
 
@@ -55,12 +56,11 @@ namespace Ocelot.Authentication.Middleware
                 if (context.User.Identity.IsAuthenticated)
                 {
                     _logger.LogDebug($"Client has been authenticated for {context.Request.Path}");
-                    _logger.LogTrace($"{MiddlwareName} invoking next middleware");
 
-                    await _next.Invoke(context);
+                    _logger.TraceInvokeNext();
-
+                        await _next.Invoke(context);
-                    _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
+                    _logger.TraceInvokeNextCompleted();
-                    _logger.LogTrace($"completed {MiddlwareName}");
+                    _logger.TraceMiddlewareCompleted();
                 }
                 else
                 {
@@ -73,18 +73,18 @@ namespace Ocelot.Authentication.Middleware
                     _logger.LogError($"Client has NOT been authenticated for {context.Request.Path} and pipeline error set. {error.ToErrorString()}");
                     SetPipelineError(error);
 
-                    _logger.LogTrace($"completed {MiddlwareName}");
+                    _logger.TraceMiddlewareCompleted();
                     return;
                 }
             }
             else
             {
-                _logger.LogTrace($"No authentication needed for {context.Request.Path}. Invoking next middleware from {MiddlwareName}");
+                _logger.LogTrace($"No authentication needed for {context.Request.Path}");
 
-                await _next.Invoke(context);
+                _logger.TraceInvokeNext();
-
+                    await _next.Invoke(context);
-                _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
+                _logger.TraceInvokeNextCompleted();
-                _logger.LogTrace($"completed {MiddlwareName}");
+                _logger.TraceMiddlewareCompleted();
             }
         }
 

src/Ocelot/DownstreamRouteFinder/Middleware/DownstreamRouteFinderMiddleware.cs

@@ -30,7 +30,7 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogTrace($"entered {MiddlwareName}");
+            _logger.TraceMiddlewareEntry();
 
             var upstreamUrlPath = context.Request.Path.ToString().SetLastCharacterAs('/');
 
@@ -43,6 +43,8 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
                 _logger.LogError($"{MiddlwareName} setting pipeline errors. IDownstreamRouteFinder returned {downstreamRoute.Errors.ToErrorString()}");
 
                 SetPipelineError(downstreamRoute.Errors);
+
+                _logger.TraceMiddlewareCompleted();
                 return;
             }
 
@@ -50,12 +52,12 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
 
             SetDownstreamRouteForThisRequest(downstreamRoute.Data);
 
-            _logger.LogTrace($"invoking next middleware from {MiddlwareName}");
+            _logger.TraceInvokeNext();
 
             await _next.Invoke(context);
 
-            _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
+            _logger.TraceInvokeNextCompleted();
-            _logger.LogTrace($"completed {MiddlwareName}");
+            _logger.TraceMiddlewareCompleted();
         }
     }
 }

src/Ocelot/RateLimit/Middleware/ClientRateLimitMiddleware.cs

@@ -31,14 +31,18 @@ namespace Ocelot.RateLimit.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogTrace($"entered {MiddlwareName}");
+            _logger.TraceMiddlewareEntry();
 
             var options = DownstreamRoute.ReRoute.RateLimitOptions;
             // check if rate limiting is enabled
             if (!DownstreamRoute.ReRoute.EnableEndpointRateLimiting)
             {
-                _logger.LogDebug($"EndpointRateLimiting is not enabled for {DownstreamRoute.ReRoute.DownstreamPathTemplate}. Invoking next middleware from {MiddlwareName}.");
+                _logger.LogDebug($"EndpointRateLimiting is not enabled for {DownstreamRoute.ReRoute.DownstreamPathTemplate}");
-                await _next.Invoke(context);
+
+                _logger.TraceInvokeNext();
+                    await _next.Invoke(context);
+                _logger.TraceInvokeNextCompleted();
+                _logger.TraceMiddlewareCompleted();
                 return;
             }
             // compute identity from request
@@ -47,8 +51,12 @@ namespace Ocelot.RateLimit.Middleware
             // check white list
             if (IsWhitelisted(identity, options))
             {
-                _logger.LogDebug($"{DownstreamRoute.ReRoute.DownstreamPathTemplate} is white listed from rate limiting. Invoking next middleware from {MiddlwareName}.");
+                _logger.LogDebug($"{DownstreamRoute.ReRoute.DownstreamPathTemplate} is white listed from rate limiting");
-                await _next.Invoke(context);
+
+                _logger.TraceInvokeNext();
+                    await _next.Invoke(context);
+                _logger.TraceInvokeNextCompleted();
+                _logger.TraceMiddlewareCompleted();
                 return;
             }
 
@@ -69,6 +77,7 @@ namespace Ocelot.RateLimit.Middleware
 
                     // break execution
                     await ReturnQuotaExceededResponse(context, options, retryAfter);
+                    _logger.TraceMiddlewareCompleted();
                     return;
                 }
             }
@@ -79,12 +88,10 @@ namespace Ocelot.RateLimit.Middleware
                 context.Response.OnStarting(SetRateLimitHeaders, state: headers);
             }
 
-            _logger.LogTrace($"invoking next middleware from {MiddlwareName}");
+            _logger.TraceInvokeNext();
-
+                await _next.Invoke(context);
-            await _next.Invoke(context);
+            _logger.TraceInvokeNextCompleted();
-
+            _logger.TraceMiddlewareCompleted();
-            _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
-            _logger.LogTrace($"completed {MiddlwareName}");
         }
 
         public virtual ClientRequestIdentity SetIdentity(HttpContext httpContext, RateLimitOptions option)

src/Ocelot/RequestId/Middleware/RequestIdMiddleware.cs

@@ -26,18 +26,16 @@ namespace Ocelot.RequestId.Middleware
 
         public async Task Invoke(HttpContext context)
         {         
-            _logger.LogTrace($"entered {MiddlwareName}");
+            _logger.TraceMiddlewareEntry();
 
             SetOcelotRequestId(context);
 
             _logger.LogDebug("set requestId");
 
-            _logger.LogTrace($"invoking next middleware from {MiddlwareName}");
+            _logger.TraceInvokeNext();
-
+                await _next.Invoke(context);
-            await _next.Invoke(context);
+            _logger.TraceInvokeNextCompleted();
-
+            _logger.TraceMiddlewareCompleted();
-            _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
-            _logger.LogTrace($"completed {MiddlwareName}");
         }
 
         private void SetOcelotRequestId(HttpContext context)

src/Ocelot/Responder/Middleware/ResponderMiddleware.cs

@@ -34,12 +34,10 @@ namespace Ocelot.Responder.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogTrace($"entered {MiddlwareName}");
+            _logger.TraceMiddlewareEntry();
-            _logger.LogTrace($"invoking next middleware from {MiddlwareName}");
+            _logger.TraceInvokeNext();
-
+                await _next.Invoke(context);
-            await _next.Invoke(context);
+            _logger.TraceInvokeNextCompleted();
-
-            _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
 
             if (PipelineError)
             {
@@ -53,7 +51,7 @@ namespace Ocelot.Responder.Middleware
                 _logger.LogDebug("no pipeline errors, setting and returning completed response");
                 await _responder.SetResponseOnHttpContext(context, HttpResponseMessage);
             }
-            _logger.LogTrace($"completed {MiddlwareName}");
+            _logger.TraceMiddlewareCompleted();
         }
 
         private void SetErrorResponse(HttpContext context, List<Error> errors)

test/Ocelot.ManualTest/appsettings.json

@@ -2,7 +2,7 @@
   "Logging": {
     "IncludeScopes": true,
     "LogLevel": {
-      "Default": "Debug",
+      "Default": "Trace",
       "System": "Information",
       "Microsoft": "Information"
     }