From 0f9006c81fae1c9bd74c284b0affa76115a89ad2 Mon Sep 17 00:00:00 2001 From: Bond_009 Date: Mon, 25 Feb 2019 18:26:17 +0100 Subject: [PATCH] Use stopwatch for more accurate measurements and reduce log spam DateTime.Now is suitible for small timespans Replaced the needlessly complex and verbose logging for the httpserver --- .../ApplicationHost.cs | 10 ++- .../HttpServer/HttpListenerHost.cs | 82 +++++-------------- .../HttpServer/LoggerUtils.cs | 55 ------------- .../ScheduledTasks/Triggers/DailyTrigger.cs | 2 +- 4 files changed, 27 insertions(+), 122 deletions(-) delete mode 100644 Emby.Server.Implementations/HttpServer/LoggerUtils.cs diff --git a/Emby.Server.Implementations/ApplicationHost.cs b/Emby.Server.Implementations/ApplicationHost.cs index 042b04b3bb..553d9b9dd8 100644 --- a/Emby.Server.Implementations/ApplicationHost.cs +++ b/Emby.Server.Implementations/ApplicationHost.cs @@ -550,16 +550,18 @@ namespace Emby.Server.Implementations var entryPoints = GetExports(); - 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 StartEntryPoints(IEnumerable entryPoints, bool isBeforeStartup) diff --git a/Emby.Server.Implementations/HttpServer/HttpListenerHost.cs b/Emby.Server.Implementations/HttpServer/HttpListenerHost.cs index d78891ac7c..29aab353d8 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 /// 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) + catch (Exception ex) when (ex is SocketException || ex is IOException || ex is OperationCanceledException) { await ErrorHandler(ex, httpReq, false, false).ConfigureAwait(false); } - - catch (IOException ex) - { - await ErrorHandler(ex, httpReq, false, false).ConfigureAwait(false); - } - - catch (SocketException ex) - { - 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 d22d9db265..0000000000 --- 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); - } - } - - /// - /// Logs the response. - /// - /// The logger. - /// The status code. - /// The URL. - /// The end point. - /// The duration. - 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 98685cebea..d33ce8a1ea 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)); }