Added logging of Sonarr API calls.

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;
+            }
+        }
+    }
+}

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" />

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)
             {

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))
             {