Merge pull request #1003 from Bond-009/stopwatch

Use stopwatch for more accurate measurements and reduce log spam

4 files changed, 27 insertions, 122 deletions

diff --git a/Emby.Server.Implementations/ApplicationHost.cs b/Emby.Server.Implementations/ApplicationHost.cs
index 042b04b3b..553d9b9dd 100644
--- a/Emby.Server.Implementations/ApplicationHost.cs
+++ b/Emby.Server.Implementations/ApplicationHost.cs
@@ -550,16 +550,18 @@ namespace Emby.Server.Implementations
 
             var entryPoints = GetExports<IServerEntryPoint>();
 
-            var now = DateTime.UtcNow;
+            var stopWatch = new Stopwatch();
+            stopWatch.Start();
             await Task.WhenAll(StartEntryPoints(entryPoints, true));
-            Logger.LogInformation("Executed all pre-startup entry points in {Elapsed:fff} ms", DateTime.Now - now);
+            Logger.LogInformation("Executed all pre-startup entry points in {Elapsed:fff} ms", stopWatch.Elapsed);
 
             Logger.LogInformation("Core startup complete");
             HttpServer.GlobalResponse = null;
 
-            now = DateTime.UtcNow;
+            stopWatch.Restart();
             await Task.WhenAll(StartEntryPoints(entryPoints, false));
-            Logger.LogInformation("Executed all post-startup entry points in {Elapsed:fff} ms", DateTime.Now - now);
+            Logger.LogInformation("Executed all post-startup entry points in {Elapsed:fff} ms", stopWatch.Elapsed);
+            stopWatch.Stop();
         }
 
         private IEnumerable<Task> StartEntryPoints(IEnumerable<IServerEntryPoint> entryPoints, bool isBeforeStartup)
diff --git a/Emby.Server.Implementations/HttpServer/HttpListenerHost.cs b/Emby.Server.Implementations/HttpServer/HttpListenerHost.cs
index d78891ac7..29aab353d 100644
--- a/Emby.Server.Implementations/HttpServer/HttpListenerHost.cs
+++ b/Emby.Server.Implementations/HttpServer/HttpListenerHost.cs
@@ -1,5 +1,6 @@
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Globalization;
 using System.IO;
 using System.Linq;
@@ -286,31 +287,6 @@ namespace Emby.Server.Implementations.HttpServer
             }
         }
 
-        private static readonly string[] _skipLogExtensions =
-        {
-            ".js",
-            ".css",
-            ".woff",
-            ".woff2",
-            ".ttf",
-            ".html"
-        };
-
-        private bool EnableLogging(string url, string localPath)
-        {
-            var extension = GetExtension(url);
-
-            return ((string.IsNullOrEmpty(extension) || !_skipLogExtensions.Contains(extension))
-                && (string.IsNullOrEmpty(localPath) || localPath.IndexOf("system/ping", StringComparison.OrdinalIgnoreCase) == -1));
-        }
-
-        private static string GetExtension(string url)
-        {
-            var parts = url.Split(new[] { '?' }, 2);
-
-            return Path.GetExtension(parts[0]);
-        }
-
         public static string RemoveQueryStringByKey(string url, string key)
         {
             var uri = new Uri(url);
@@ -448,10 +424,9 @@ namespace Emby.Server.Implementations.HttpServer
         /// </summary>
         protected async Task RequestHandler(IHttpRequest httpReq, string urlString, string host, string localPath, CancellationToken cancellationToken)
         {
-            var date = DateTime.Now;
+            var stopWatch = new Stopwatch();
+            stopWatch.Start();
             var httpRes = httpReq.Response;
-            bool enableLog = false;
-            bool logHeaders = false;
             string urlToLog = null;
             string remoteIp = httpReq.RemoteIp;
 
@@ -498,18 +473,8 @@ namespace Emby.Server.Implementations.HttpServer
                     return;
                 }
 
-                var operationName = httpReq.OperationName;
-
-                enableLog = EnableLogging(urlString, localPath);
-                urlToLog = urlString;
-                logHeaders = enableLog && urlToLog.IndexOf("/videos/", StringComparison.OrdinalIgnoreCase) != -1;
-
-                if (enableLog)
-                {
-                    urlToLog = GetUrlToLog(urlString);
-
-                    LoggerUtils.LogRequest(_logger, urlToLog, httpReq.HttpMethod, httpReq.UserAgent, logHeaders ? httpReq.Headers : null);
-                }
+                urlToLog = GetUrlToLog(urlString);
+                Logger.LogDebug("HTTP {HttpMethod} {Url} UserAgent: {UserAgent} \nHeaders: {@Headers}", urlToLog, httpReq.UserAgent ?? string.Empty, httpReq.HttpMethod, httpReq.Headers);
 
                 if (string.Equals(localPath, "/emby/", StringComparison.OrdinalIgnoreCase) ||
                     string.Equals(localPath, "/mediabrowser/", StringComparison.OrdinalIgnoreCase))
@@ -517,6 +482,7 @@ namespace Emby.Server.Implementations.HttpServer
                     RedirectToUrl(httpRes, DefaultRedirectPath);
                     return;
                 }
+
                 if (string.Equals(localPath, "/emby", StringComparison.OrdinalIgnoreCase) ||
                     string.Equals(localPath, "/mediabrowser", StringComparison.OrdinalIgnoreCase))
                 {
@@ -562,16 +528,19 @@ namespace Emby.Server.Implementations.HttpServer
                     RedirectToUrl(httpRes, DefaultRedirectPath);
                     return;
                 }
+
                 if (string.Equals(localPath, "/web/", StringComparison.OrdinalIgnoreCase))
                 {
                     RedirectToUrl(httpRes, "../" + DefaultRedirectPath);
                     return;
                 }
+
                 if (string.Equals(localPath, "/", StringComparison.OrdinalIgnoreCase))
                 {
                     RedirectToUrl(httpRes, DefaultRedirectPath);
                     return;
                 }
+
                 if (string.IsNullOrEmpty(localPath))
                 {
                     RedirectToUrl(httpRes, "/" + DefaultRedirectPath);
@@ -607,33 +576,21 @@ namespace Emby.Server.Implementations.HttpServer
 
                 if (handler != null)
                 {
-                    await handler.ProcessRequestAsync(this, httpReq, httpRes, Logger, operationName, cancellationToken).ConfigureAwait(false);
+                    await handler.ProcessRequestAsync(this, httpReq, httpRes, Logger, httpReq.OperationName, cancellationToken).ConfigureAwait(false);
                 }
                 else
                 {
                     await ErrorHandler(new FileNotFoundException(), httpReq, false, false).ConfigureAwait(false);
                 }
             }
-            catch (OperationCanceledException ex)
-            {
-                await ErrorHandler(ex, httpReq, false, false).ConfigureAwait(false);
-            }
-
-            catch (IOException ex)
-            {
-                await ErrorHandler(ex, httpReq, false, false).ConfigureAwait(false);
-            }
-
-            catch (SocketException ex)
+            catch (Exception ex) when (ex is SocketException || ex is IOException || ex is OperationCanceledException)
             {
                 await ErrorHandler(ex, httpReq, false, false).ConfigureAwait(false);
             }
-
             catch (SecurityException ex)
             {
                 await ErrorHandler(ex, httpReq, false, true).ConfigureAwait(false);
             }
-
             catch (Exception ex)
             {
                 var logException = !string.Equals(ex.GetType().Name, "SocketException", StringComparison.OrdinalIgnoreCase);
@@ -644,13 +601,15 @@ namespace Emby.Server.Implementations.HttpServer
             {
                 httpRes.Close();
 
-                if (enableLog)
+                stopWatch.Stop();
+                var elapsed = stopWatch.Elapsed;
+                if (elapsed.Milliseconds > 500)
                 {
-                    var statusCode = httpRes.StatusCode;
-
-                    var duration = DateTime.Now - date;
-
-                    LoggerUtils.LogResponse(_logger, statusCode, urlToLog, remoteIp, duration, logHeaders ? httpRes.Headers : null);
+                    _logger.LogWarning("HTTP Response {StatusCode} to {RemoteIp}. Time (slow): {Elapsed:ss.fff}. {Url}", httpRes.StatusCode, remoteIp, stopWatch.Elapsed, urlToLog);
+                }
+                else
+                {
+                    _logger.LogDebug("HTTP Response {StatusCode} to {RemoteIp}. Time: {Elapsed:ss.fff}. {Url}", httpRes.StatusCode, remoteIp, stopWatch.Elapsed, urlToLog);
                 }
             }
         }
@@ -663,12 +622,11 @@ namespace Emby.Server.Implementations.HttpServer
             var pathParts = pathInfo.TrimStart('/').Split('/');
             if (pathParts.Length == 0)
             {
-                _logger.LogError("Path parts empty for PathInfo: {pathInfo}, Url: {RawUrl}", pathInfo, httpReq.RawUrl);
+                _logger.LogError("Path parts empty for PathInfo: {PathInfo}, Url: {RawUrl}", pathInfo, httpReq.RawUrl);
                 return null;
             }
 
             var restPath = ServiceHandler.FindMatchingRestPath(httpReq.HttpMethod, pathInfo, out string contentType);
-
             if (restPath != null)
             {
                 return new ServiceHandler
diff --git a/Emby.Server.Implementations/HttpServer/LoggerUtils.cs b/Emby.Server.Implementations/HttpServer/LoggerUtils.cs
deleted file mode 100644
index d22d9db26..000000000
--- a/Emby.Server.Implementations/HttpServer/LoggerUtils.cs
+++ /dev/null
@@ -1,55 +0,0 @@
-using System;
-using System.Globalization;
-using MediaBrowser.Model.Services;
-using Microsoft.Extensions.Logging;
-
-namespace Emby.Server.Implementations.HttpServer
-{
-    public static class LoggerUtils
-    {
-        public static void LogRequest(ILogger logger, string url, string method, string userAgent, QueryParamCollection headers)
-        {
-            if (headers == null)
-            {
-                logger.LogInformation("{0} {1}. UserAgent: {2}", "HTTP " + method, url, userAgent ?? string.Empty);
-            }
-            else
-            {
-                var headerText = string.Empty;
-                var index = 0;
-
-                foreach (var i in headers)
-                {
-                    if (index > 0)
-                    {
-                        headerText += ", ";
-                    }
-
-                    headerText += i.Name + "=" + i.Value;
-
-                    index++;
-                }
-
-                logger.LogInformation("HTTP {0} {1}. {2}", method, url, headerText);
-            }
-        }
-
-        /// <summary>
-        /// Logs the response.
-        /// </summary>
-        /// <param name="logger">The logger.</param>
-        /// <param name="statusCode">The status code.</param>
-        /// <param name="url">The URL.</param>
-        /// <param name="endPoint">The end point.</param>
-        /// <param name="duration">The duration.</param>
-        public static void LogResponse(ILogger logger, int statusCode, string url, string endPoint, TimeSpan duration, QueryParamCollection headers)
-        {
-            var durationMs = duration.TotalMilliseconds;
-            var logSuffix = durationMs >= 1000 && durationMs < 60000 ? "ms (slow)" : "ms";
-
-            //var headerText = headers == null ? string.Empty : "Headers: " + string.Join(", ", headers.Where(i => i.Name.IndexOf("Access-", StringComparison.OrdinalIgnoreCase) == -1).Select(i => i.Name + "=" + i.Value).ToArray());
-            var headerText = string.Empty;
-            logger.LogInformation("HTTP Response {0} to {1}. Time: {2}{3}. {4} {5}", statusCode, endPoint, Convert.ToInt32(durationMs).ToString(CultureInfo.InvariantCulture), logSuffix, url, headerText);
-        }
-    }
-}
diff --git a/Emby.Server.Implementations/ScheduledTasks/Triggers/DailyTrigger.cs b/Emby.Server.Implementations/ScheduledTasks/Triggers/DailyTrigger.cs
index 98685cebe..d33ce8a1e 100644
--- a/Emby.Server.Implementations/ScheduledTasks/Triggers/DailyTrigger.cs
+++ b/Emby.Server.Implementations/ScheduledTasks/Triggers/DailyTrigger.cs
@@ -44,7 +44,7 @@ namespace Emby.Server.Implementations.ScheduledTasks
 
             var dueTime = triggerDate - now;
 
-            logger.LogInformation("Daily trigger for {0} set to fire at {1}, which is {2} minutes from now.", taskName, triggerDate.ToString(), dueTime.TotalMinutes.ToString(CultureInfo.InvariantCulture));
+            logger.LogInformation("Daily trigger for {0} set to fire at {1}, which is {2} minutes from now.", taskName, triggerDate, dueTime);
 
             Timer = new Timer(state => OnTriggered(), null, dueTime, TimeSpan.FromMilliseconds(-1));
         }