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 @@ + 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 @@ namespace NzbDrone.Common.Http 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 @@ namespace NzbDrone.Common.Http 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)) {