cotugno/jellyfin
2
Fork 0
mirror of https://github.com/jellyfin/jellyfin.git synced 2024-11-15 18:08:53 -07:00
Code Issues Packages Projects Releases Wiki Activity

Use stopwatch for more accurate measurements and reduce log spam

Browse Source 
DateTime.Now is suitible for small timespans
Replaced the needlessly complex and verbose logging for the httpserver
This commit is contained in:
Bond_009 2019-02-25 18:26:17 +01:00
parent b3438559cc
commit 0f9006c81f
4 changed files with 27 additions and 122 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
Emby.Server.Implementations/ApplicationHost.cs
View File

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

80
Emby.Server.Implementations/HttpServer/HttpListenerHost.cs
View File

@ -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);
}
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

55
Emby.Server.Implementations/HttpServer/LoggerUtils.cs
View File

@ -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);
}
}
}

2
Emby.Server.Implementations/ScheduledTasks/Triggers/DailyTrigger.cs
View File

@ -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));
}