From 229986033c1e0360e0ef192ef035403676b94dc5 Mon Sep 17 00:00:00 2001
From: Taloth Saldono <Taloth@users.noreply.github.com>
Date: Wed, 11 May 2016 21:13:31 +0200
Subject: [PATCH] Added logging of Sonarr API calls.

---
 .../Pipelines/RequestLoggingPipeline.cs       | 67 +++++++++++++++++++
 src/NzbDrone.Api/NzbDrone.Api.csproj          |  1 +
 src/NzbDrone.Common/Http/HttpClient.cs        |  2 +-
 src/NzbDrone.Common/Http/HttpResponse.cs      |  2 +-
 4 files changed, 70 insertions(+), 2 deletions(-)
 create mode 100644 src/NzbDrone.Api/Extensions/Pipelines/RequestLoggingPipeline.cs

diff --git a/src/NzbDrone.Api/Extensions/Pipelines/RequestLoggingPipeline.cs b/src/NzbDrone.Api/Extensions/Pipelines/RequestLoggingPipeline.cs
new file mode 100644
index 000000000..381d4e1cb
--- /dev/null
+++ b/src/NzbDrone.Api/Extensions/Pipelines/RequestLoggingPipeline.cs
@@ -0,0 +1,67 @@
+using System;
+using System.Threading;
+using Nancy;
+using Nancy.Bootstrapper;
+using NLog;
+using NzbDrone.Common.Extensions;
+
+namespace NzbDrone.Api.Extensions.Pipelines
+{
+    public class RequestLoggingPipeline : IRegisterNancyPipeline
+    {
+        private static readonly Logger _loggerHttp = LogManager.GetLogger("Http");
+        private static readonly Logger _loggerApi = LogManager.GetLogger("Api");
+
+        private static int _requestSequenceID;
+
+        public void Register(IPipelines pipelines)
+        {
+            pipelines.BeforeRequest.AddItemToStartOfPipeline(LogStart);
+            pipelines.AfterRequest.AddItemToEndOfPipeline(LogEnd);
+        }
+
+        private Response LogStart(NancyContext context)
+        {
+            var id = Interlocked.Increment(ref _requestSequenceID);
+
+            context.Items["ApiRequestSequenceID"] = id;
+            context.Items["ApiRequestStartTime"] = DateTime.UtcNow;
+
+            var reqPath = GetRequestPathAndQuery(context.Request);
+            
+            _loggerHttp.Trace("Req: {0} [{1}] {2}", id, context.Request.Method, reqPath);
+
+            return null;
+        }
+
+        private void LogEnd(NancyContext context)
+        {
+            var id = (int)context.Items["ApiRequestSequenceID"];
+            var startTime = (DateTime)context.Items["ApiRequestStartTime"];
+
+            var endTime = DateTime.UtcNow;
+            var duration = endTime - startTime;
+
+            var reqPath = GetRequestPathAndQuery(context.Request);
+
+            _loggerHttp.Trace("Res: {0} [{1}] {2}: {3}.{4} ({5} ms)", id, context.Request.Method, reqPath, (int)context.Response.StatusCode, context.Response.StatusCode, (int)duration.TotalMilliseconds);
+
+            if (context.Request.IsApiRequest())
+            {
+                _loggerApi.Debug("[{0}] {1}: {2}.{3} ({4} ms)", context.Request.Method, reqPath, (int)context.Response.StatusCode, context.Response.StatusCode, (int)duration.TotalMilliseconds);
+            }
+        }
+
+        private static string GetRequestPathAndQuery(Request request)
+        {
+            if (request.Url.Query.IsNotNullOrWhiteSpace())
+            {
+                return string.Concat(request.Url.Path, "?", request.Url.Query);
+            }
+            else
+            {
+                return request.Url.Path;
+            }
+        }
+    }
+}
\ No newline at end of file
diff --git a/src/NzbDrone.Api/NzbDrone.Api.csproj b/src/NzbDrone.Api/NzbDrone.Api.csproj
index a92f18cfb..54100a4aa 100644
--- a/src/NzbDrone.Api/NzbDrone.Api.csproj
+++ b/src/NzbDrone.Api/NzbDrone.Api.csproj
@@ -100,6 +100,7 @@
     <Compile Include="Commands\CommandResource.cs" />
     <Compile Include="Extensions\AccessControlHeaders.cs" />
     <Compile Include="Extensions\Pipelines\CorsPipeline.cs" />
+    <Compile Include="Extensions\Pipelines\RequestLoggingPipeline.cs" />
     <Compile Include="Frontend\Mappers\LoginHtmlMapper.cs" />
     <Compile Include="Frontend\Mappers\RobotsTxtMapper.cs" />
     <Compile Include="Indexers\ReleaseModuleBase.cs" />
diff --git a/src/NzbDrone.Common/Http/HttpClient.cs b/src/NzbDrone.Common/Http/HttpClient.cs
index baf78a2f3..8c4f5968c 100644
--- a/src/NzbDrone.Common/Http/HttpClient.cs
+++ b/src/NzbDrone.Common/Http/HttpClient.cs
@@ -74,7 +74,7 @@ public HttpResponse Execute(HttpRequest request)
 
             stopWatch.Stop();
 
-            _logger.Trace("{0} ({1:n0} ms)", response, stopWatch.ElapsedMilliseconds);
+            _logger.Trace("{0} ({1} ms)", response, stopWatch.ElapsedMilliseconds);
 
             foreach (var interceptor in _requestInterceptors)
             {
diff --git a/src/NzbDrone.Common/Http/HttpResponse.cs b/src/NzbDrone.Common/Http/HttpResponse.cs
index 1b64c76d7..bbbf71d11 100644
--- a/src/NzbDrone.Common/Http/HttpResponse.cs
+++ b/src/NzbDrone.Common/Http/HttpResponse.cs
@@ -79,7 +79,7 @@ public Dictionary<string, string> GetCookies()
 
         public override string ToString()
         {
-            var result = string.Format("Res: [{0}] {1} : {2}.{3}", Request.Method, Request.Url, (int)StatusCode, StatusCode);
+            var result = string.Format("Res: [{0}] {1}: {2}.{3}", Request.Method, Request.Url, (int)StatusCode, StatusCode);
 
             if (HasHttpError && Headers.ContentType.IsNotNullOrWhiteSpace() && !Headers.ContentType.Equals("text/html", StringComparison.InvariantCultureIgnoreCase))
             {