Improve logging

src/Mockaco/Extensions/HttpRequestExtensions.cs

@@ -22,10 +22,13 @@ OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
 SOFTWARE.
 */
 
+using Microsoft.AspNetCore.Http.Internal;
 using Microsoft.Net.Http.Headers;
 using Mockaco.Routing;
 using System;
+using System.IO;
 using System.Text;
+using System.Threading.Tasks;
 
 namespace Microsoft.AspNetCore.Http
 {
@@ -87,5 +90,21 @@ public static bool HasJsonContentType(this HttpRequest request)
 
             return parsedValue?.MediaType.Equals("application/json", StringComparison.OrdinalIgnoreCase) == true;
         }
+
+        public static string ReadBodyStream(this HttpRequest httpRequest)
+        {
+            httpRequest.EnableRewind();
+
+            var reader = new StreamReader(httpRequest.Body);
+
+            var body = reader.ReadToEnd();
+
+            if (httpRequest.Body.CanSeek)
+            {
+                httpRequest.Body.Seek(0, SeekOrigin.Begin);
+            }
+
+            return body;
+        }
     }
 }

src/Mockaco/Middlewares/CallbackMiddleware.cs

@@ -57,7 +57,7 @@ private async Task PerformCallback(HttpContext httpContext, IMockacoContext mock
 
                 stopwatch.Restart();
 
-                _logger.LogDebug("Callback starting");
+                _logger.LogDebug("Callback started");
 
                 await PerformRequest(request, httpClient);
 
@@ -130,7 +130,7 @@ private async Task DelayRequest(CallbackTemplate callbackTemplate, long elapsedM
             var remainingDelay = TimeSpan.FromMilliseconds(callbackTemplate.Delay.GetValueOrDefault() - elapsedMilliseconds);
             if (elapsedMilliseconds < remainingDelay.TotalMilliseconds)
             {
-                _logger.LogDebug("Waiting {0} ms to perform callback on time", remainingDelay.TotalMilliseconds);
+                _logger.LogDebug("Callback delay: {0} milliseconds", remainingDelay.TotalMilliseconds);
                 await Task.Delay(remainingDelay);
             }
         }

src/Mockaco/Middlewares/RequestMatchingMiddleware.cs

@@ -10,39 +10,39 @@ namespace Mockaco.Middlewares
     public class RequestMatchingMiddleware
     {
         private readonly RequestDelegate _next;
-
-        public RequestMatchingMiddleware(RequestDelegate next)
+        private readonly ILogger<RequestMatchingMiddleware> _logger;
+
+        public RequestMatchingMiddleware(RequestDelegate next, ILogger<RequestMatchingMiddleware> logger)
         {
             _next = next;
+            _logger = logger;
         }
 
         public async Task Invoke(
             HttpContext httpContext,
             IMockacoContext mockacoContext,
             IScriptContext scriptContext,
             IRouteProvider routerProvider,
-            ITemplateTransformer templateTransformer,
-            ILogger<RequestMatchingMiddleware> logger)
+            ITemplateTransformer templateTransformer
+            )
         {
             scriptContext.AttachHttpContext(httpContext);
 
-            logger.LogInformation("Incoming request from {remoteIp}", httpContext.Connection.RemoteIpAddress);
-            logger.LogDebug("Headers: {headers}", scriptContext.Request.Header.ToJson());
-            logger.LogDebug("Body: {body}", scriptContext.Request.Body.ToString());
+            LogRequest(httpContext);
 
             foreach (var route in routerProvider.GetRoutes())
             {
                 if (RouteMatchesRequest(httpContext.Request, route))
                 {
                     scriptContext.AttachRoute(httpContext, route);
-                    
+
                     var template = await templateTransformer.Transform(route.RawTemplate, scriptContext);
 
-                    var evaluatedCondition = template.Request.Condition ?? true;
-                                        
-                    if (evaluatedCondition)
+                    var matchesCondition = template.Request.Condition ?? true;
+
+                    if (matchesCondition)
                     {
-                        logger.LogInformation("Incoming request matches route {route}", route);
+                        _logger.LogInformation("Incoming request matched route {route}", route);
 
                         mockacoContext.Route = route;
                         mockacoContext.TransformedTemplate = template;
@@ -53,20 +53,38 @@ public async Task Invoke(
                     }
                     else
                     {
-                        logger.LogInformation("Incoming request didn't match condition for route {route}", route);
+                        _logger.LogInformation("Incoming request didn't match condition for route {route}", route);
                     }
                 }
                 else
                 {
-                    logger.LogDebug("Incoming request didn't match route {route}", route);
+                    _logger.LogDebug("Incoming request didn't match route {route}", route);
                 }
             }
 
-            logger.LogInformation("Incoming request didn't match any route");
+            _logger.LogInformation("Incoming request didn't match any route");
 
             httpContext.Response.StatusCode = StatusCodes.Status501NotImplemented;
         }
 
+        private void LogRequest(HttpContext httpContext)
+        {
+            _logger.LogInformation("Incoming request from {remoteIp}", httpContext.Connection.RemoteIpAddress);
+
+            _logger.LogDebug("Headers: {headers}", httpContext.Request.Headers.ToJson());
+
+            var body = httpContext.Request.ReadBodyStream();
+
+            if (string.IsNullOrEmpty(body))
+            {
+                _logger.LogDebug("Body is not present", body);
+            }
+            else
+            {
+                _logger.LogDebug("Body: {body}", body);
+            }
+        }
+
         private static bool RouteMatchesRequest(HttpRequest request, Route route)
         {
             if (!string.IsNullOrWhiteSpace(route.Method))

src/Mockaco/Middlewares/ResponseDelayMiddleware.cs

@@ -29,7 +29,7 @@ public async Task Invoke(HttpContext httpContext, IMockacoContext mockacoContext
             var remainingDelay = responseDelay - (int)stopwatch.ElapsedMilliseconds;
             if (remainingDelay > 0)
             {
-                logger.LogDebug($"Delaying the response for at least {responseDelay} milliseconds");
+                logger.LogDebug("Response delay: {responseDelay} milliseconds", responseDelay);
 
                 await Task.Delay(remainingDelay);
             }

src/Mockaco/Mocks/HelloWorld-200.json

@@ -1,13 +1,38 @@
 {
+  "variables": {
+    "id": "<#= Faker.Random.Guid()  #>"
+  },
   "request": {
     "method": "GET",
     "route": "hello/{message}",
+    "condition": null
   },
   "response": {
+    "delay": <#= Faker.Random.Number(1, 5000) #>,
+    "status": "OK",
     "body": {
       "id": "<#= Faker.Random.Guid() #>",
-      "message": "Hello <#= Request.Route["message"] #>!",
+      "message": "<#= Request.Route["message"] #>",
+      "product": "<#= Faker.Commerce.ProductName() #>",
+      "inexistent header item": "<#= Request.Header["inexistent"] #>",
+      "inexistent body item": "<#= Request.Body["inexistent"] #>",
+      "existent body item": "<#= Request.Body["message"] #>",
       "createdAt": <#= JsonConvert.SerializeObject(System.DateTime.Now) #>
+    },
+	"indented": true
+  },
+  "callback": {
+    "delay": 5000,
+    "method": "POST",
+    "url": "https://postman-echo.com/post",
+    "timeout": 2000,
+    "headers": {
+      "X-Foo": "Bar"
+    },
+    "body": {
+      "requestRoute": "The callback informs that Request.Route[\"message\"] was <#= Request.Route["message"] #>",
+      "requestBody": "The callback informs that Request.Body[\"message\"] was <#= Request.Body["message"] #>",
+      "responseBody": "The callback informs that Response.Body[\"id\"] was <#= Response.Body["id"] #>"
     }
   }
 }

src/Mockaco/Scripting/ScriptContext.cs

@@ -92,19 +92,10 @@ private static JObject ParseFormDataBody(HttpRequest httpRequest)
         }
 
         private static JObject ParseJsonBody(HttpRequest httpRequest)
-        {
-            httpRequest.EnableRewind();
-
-            var reader = new StreamReader(httpRequest.Body);
-
-            var json = reader.ReadToEnd();
-
-            if (httpRequest.Body.CanSeek)
-            {
-                httpRequest.Body.Seek(0, SeekOrigin.Begin);
-            }
-
-            return !string.IsNullOrWhiteSpace(json) ? JObject.Parse(json) : new JObject();
+        {      
+            var body = httpRequest.ReadBodyStream();
+
+            return !string.IsNullOrWhiteSpace(body) ? JObject.Parse(body) : new JObject();
         }
     }
 }

src/Mockaco/Scripting/ScriptRunnerFactory.cs

@@ -67,7 +67,7 @@ public ScriptRunner<TResult> CreateRunner<TContext, TResult>(string code, out Sc
 
             runner = script.CreateDelegate();
 
-            _logger.LogTrace($"Created runner in {stopWatch.ElapsedMilliseconds}ms");
+            _logger.LogTrace("Created runner in {elapsedTime} milliseconds", stopWatch.ElapsedMilliseconds);
 
             return runner;
         }

src/Mockaco/Templating/Providers/TemplateFileProvider.cs

@@ -76,7 +76,7 @@ public IEnumerable<IRawTemplate> GetTemplates()
 
         private void PostEvictionCallback(object key, object value, EvictionReason reason, object state)
         {
-            _logger.LogDebug($"Cache invalidated because of {reason}");
+            _logger.LogDebug("Cache invalidated because of {reason}", reason);
         }
 
         private static IEnumerable<IRawTemplate> LoadTemplatesFromDirectory()