From 171e3a7b22eb2a091c31c194eabf5f8538ccccd2 Mon Sep 17 00:00:00 2001
From: Masoud Bahrami <mbahrami1990@gmail.com>
Date: Tue, 27 Feb 2024 19:05:39 +0330
Subject: [PATCH] Logging bug in `HttpRequesterMiddleware` (#1953)

* Fix a bug in HttpRequesterMiddleware.cs,

BadRequest should be logged as debug!

* Clean code: refactor `CreateLogBasedOnResponse`

* Unit tests

* Remove redundant if-checking

---------

Co-authored-by: Raman Maksimchuk <dotnet044@gmail.com>
---
 .../Middleware/HttpRequesterMiddleware.cs     | 16 +++++---
 .../Requester/HttpRequesterMiddlewareTests.cs | 38 +++++++++++++++----
 2 files changed, 40 insertions(+), 14 deletions(-)

diff --git a/src/Ocelot/Requester/Middleware/HttpRequesterMiddleware.cs b/src/Ocelot/Requester/Middleware/HttpRequesterMiddleware.cs
index e26d6a5b3..2855437f0 100644
--- a/src/Ocelot/Requester/Middleware/HttpRequesterMiddleware.cs
+++ b/src/Ocelot/Requester/Middleware/HttpRequesterMiddleware.cs
@@ -39,15 +39,19 @@ public async Task Invoke(HttpContext httpContext)
 
         private void CreateLogBasedOnResponse(Response<HttpResponseMessage> response)
         {
-            if (response.Data?.StatusCode <= HttpStatusCode.BadRequest)
+            var status = response.Data?.StatusCode ?? HttpStatusCode.Processing;
+            var reason = response.Data?.ReasonPhrase ?? "unknown";
+            var uri = response.Data?.RequestMessage?.RequestUri?.ToString() ?? string.Empty;
+
+            string message() => $"{(int)status} ({reason}) status code of request URI: {uri}.";
+
+            if (status < HttpStatusCode.BadRequest)
             {
-                Logger.LogInformation(() =>
-                    $"{(int)response.Data.StatusCode} ({response.Data.ReasonPhrase}) status code, request uri: {response.Data.RequestMessage?.RequestUri}");
+                Logger.LogInformation(message);
             }
-            else if (response.Data?.StatusCode >= HttpStatusCode.BadRequest)
+            else
             {
-                Logger.LogWarning(
-                    () => $"{(int)response.Data.StatusCode} ({response.Data.ReasonPhrase}) status code, request uri: {response.Data.RequestMessage?.RequestUri}");
+                Logger.LogWarning(message);
             }
         }
     }
diff --git a/test/Ocelot.UnitTests/Requester/HttpRequesterMiddlewareTests.cs b/test/Ocelot.UnitTests/Requester/HttpRequesterMiddlewareTests.cs
index 3dda1467c..717ca04ad 100644
--- a/test/Ocelot.UnitTests/Requester/HttpRequesterMiddlewareTests.cs
+++ b/test/Ocelot.UnitTests/Requester/HttpRequesterMiddlewareTests.cs
@@ -34,7 +34,7 @@ public HttpRequesterMiddlewareTests()
         public void should_call_services_correctly()
         {
             this.Given(x => x.GivenTheRequestIs())
-                .And(x => x.GivenTheRequesterReturns(new OkResponse<HttpResponseMessage>(new HttpResponseMessage(System.Net.HttpStatusCode.OK))))
+                .And(x => x.GivenTheRequesterReturns(new OkResponse<HttpResponseMessage>(new HttpResponseMessage(HttpStatusCode.OK))))
                 .When(x => x.WhenICallTheMiddleware())
                 .Then(x => x.ThenTheDownstreamResponseIsSet())
                 .Then(x => InformationIsLogged())
@@ -56,12 +56,38 @@ public void should_log_downstream_internal_server_error()
         {
             this.Given(x => x.GivenTheRequestIs())
                     .And(x => x.GivenTheRequesterReturns(
-                        new OkResponse<HttpResponseMessage>(new HttpResponseMessage(System.Net.HttpStatusCode.InternalServerError))))
+                        new OkResponse<HttpResponseMessage>(new HttpResponseMessage(HttpStatusCode.InternalServerError))))
                 .When(x => x.WhenICallTheMiddleware())
                 .Then(x => x.WarningIsLogged())
                 .BDDfy();
         }
+
+        [Theory]
+        [Trait("Bug", "1953")]
+        [InlineData(HttpStatusCode.OK)]
+        [InlineData(HttpStatusCode.PermanentRedirect)]
+        public void Should_LogInformation_when_status_is_less_than_BadRequest(HttpStatusCode status)
+        {
+            this.Given(x => x.GivenTheRequestIs())
+                .And(x => x.GivenTheRequesterReturns(new OkResponse<HttpResponseMessage>(new HttpResponseMessage(status))))
+                .When(x => x.WhenICallTheMiddleware())
+                .Then(x => x.InformationIsLogged())
+                .BDDfy();
+        }
 
+        [Theory]
+        [Trait("Bug", "1953")]
+        [InlineData(HttpStatusCode.BadRequest)]
+        [InlineData(HttpStatusCode.NotFound)]
+        public void Should_LogWarning_when_status_is_BadRequest_or_greater(HttpStatusCode status)
+        {
+            this.Given(x => x.GivenTheRequestIs())
+                .And(x => x.GivenTheRequesterReturns(new OkResponse<HttpResponseMessage>(new HttpResponseMessage(status))))
+                .When(x => x.WhenICallTheMiddleware())
+                .Then(x => x.WarningIsLogged())
+                .BDDfy();
+        }
+
         private void ThenTheErrorIsSet()
         {
             _httpContext.Items.Errors().Count.ShouldBeGreaterThan(0);
@@ -103,18 +129,14 @@ private void ThenTheDownstreamResponseIsSet()
         private void WarningIsLogged()
         {
             _logger.Verify(
-                x => x.LogWarning(
-                    It.IsAny<Func<string>>()
-                   ),
+                x => x.LogWarning(It.IsAny<Func<string>>()),
                 Times.Once);
         }
 
         private void InformationIsLogged()
         {
             _logger.Verify(
-                x => x.LogInformation(
-                    It.IsAny<Func<string>>()
-                ),
+                x => x.LogInformation(It.IsAny<Func<string>>()),
                 Times.Once);
         }
     }