private void TraceTraffic(RavenBaseApiController controller, LogHttpRequestStatsParams logHttpRequestStatsParams, string databaseName)
{
if (HasAnyHttpTraceEventTransport() == false)
return;
NotifyTrafficWatch(
new TrafficWatchNotification()
{
RequestUri = logHttpRequestStatsParams.RequestUri,
ElapsedMilliseconds = logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds,
CustomInfo = logHttpRequestStatsParams.CustomInfo,
HttpMethod = logHttpRequestStatsParams.HttpMethod,
ResponseStatusCode = logHttpRequestStatsParams.ResponseStatusCode,
TenantName = NormalizeTennantName(databaseName),
TimeStamp = SystemTime.UtcNow,
InnerRequestsCount = logHttpRequestStatsParams.InnerRequestsCount
}
);
}
private void LogHttpRequestStats(RavenBaseApiController controller, LogHttpRequestStatsParams logHttpRequestStatsParams, string databaseName, long curReq)
{
if (Logger.IsDebugEnabled == false)
return;
if (controller is StudioController || controller is HardRouteController || controller is SilverlightController)
return;
// we filter out requests for the UI because they fill the log with information
// we probably don't care about them anyway. That said, we do output them if they take too
// long.
if (logHttpRequestStatsParams.Headers["Raven-Timer-Request"] == "true" &&
logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds <= 25)
return;
var message = string.Format(CultureInfo.InvariantCulture, "Request #{0,4:#,0}: {1,-7} - {2,5:#,0} ms - {5,-10} - {3} - {4}",
curReq,
logHttpRequestStatsParams.HttpMethod,
logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds,
logHttpRequestStatsParams.ResponseStatusCode,
logHttpRequestStatsParams.RequestUri,
databaseName);
Logger.Debug(message);
if (string.IsNullOrWhiteSpace(logHttpRequestStatsParams.CustomInfo) == false)
{
Logger.Debug(logHttpRequestStatsParams.CustomInfo);
}
}
private void RememberRecentRequests(LogHttpRequestStatsParams requestLog, string databaseName)
{
if (string.IsNullOrWhiteSpace(databaseName))
databaseName = Constants.SystemDatabase;
var traces = tracedRequests.GetOrAdd(databaseName, new ConcurrentQueue<LogHttpRequestStatsParams>());
LogHttpRequestStatsParams _;
while (traces.Count > 50 && traces.TryDequeue(out _))
{
}
traces.Enqueue(requestLog);
}
private void FinalizeRequestProcessing(RavenBaseApiController controller, HttpResponseMessage response, Stopwatch sw)
{
LogHttpRequestStatsParams logHttpRequestStatsParam = null;
try
{
StringBuilder sb = null;
if (controller.CustomRequestTraceInfo != null && controller.CustomRequestTraceInfo.Count > 0)
{
sb = new StringBuilder();
foreach (var action in controller.CustomRequestTraceInfo)
{
action(sb);
sb.AppendLine();
}
while (sb.Length > 0)
{
if (!char.IsWhiteSpace(sb[sb.Length - 1]))
break;
sb.Length--;
}
}
logHttpRequestStatsParam = new LogHttpRequestStatsParams(
sw,
GetHeaders(controller.InnerHeaders),
controller.InnerRequest.Method.Method,
response != null ? (int)response.StatusCode : 500,
controller.InnerRequest.RequestUri.ToString(),
sb != null ? sb.ToString() : null,
controller.InnerRequestsCount
);
}
catch (Exception e)
{
Logger.WarnException("Could not gather information to log request stats", e);
}
if (logHttpRequestStatsParam == null || sw == null)
return;
sw.Stop();
if (landlord.IsDatabaseLoaded(controller.TenantName ?? Constants.SystemDatabase))
{
controller.MarkRequestDuration(sw.ElapsedMilliseconds);
}
var curReq = Interlocked.Increment(ref reqNum);
LogHttpRequestStats(controller, logHttpRequestStatsParam, controller.TenantName, curReq);
if (controller.IsInternalRequest == false)
{
TraceTraffic(controller, logHttpRequestStatsParam, controller.TenantName);
}
RememberRecentRequests(logHttpRequestStatsParam, controller.TenantName);
}
private void LogHttpRequestStats(LogHttpRequestStatsParams logHttpRequestStatsParams, string databaseName)
{
if (Logger.IsDebugEnabled == false)
return;
// we filter out requests for the UI because they fill the log with information
// we probably don't care about them anyway. That said, we do output them if they take too
// long.
if (logHttpRequestStatsParams.Headers["Raven-Timer-Request"] == "true" &&
logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds <= 25)
return;
var curReq = Interlocked.Increment(ref reqNum);
Logger.Debug("Request #{0,4:#,0}: {1,-7} - {2,5:#,0} ms - {5,-10} - {3} - {4}",
curReq,
logHttpRequestStatsParams.HttpMethod,
logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds,
logHttpRequestStatsParams.ResponseStatusCode,
logHttpRequestStatsParams.RequestUri,
databaseName);
if (string.IsNullOrWhiteSpace(logHttpRequestStatsParams.CustomInfo) == false)
Logger.Debug(logHttpRequestStatsParams.CustomInfo);
}
private void FinalizeRequestProcessing(RavenBaseApiController controller, HttpResponseMessage response, Stopwatch sw)
{
LogHttpRequestStatsParams logHttpRequestStatsParam = null;
try
{
StringBuilder sb = null;
if (controller.CustomRequestTraceInfo != null)
{
sb = new StringBuilder();
foreach (var action in controller.CustomRequestTraceInfo)
{
action(sb);
sb.AppendLine();
}
while (sb.Length > 0)
{
if (!char.IsWhiteSpace(sb[sb.Length - 1]))
break;
sb.Length--;
}
}
logHttpRequestStatsParam = new LogHttpRequestStatsParams(
sw,
GetHeaders(controller.InnerHeaders),
controller.InnerRequest.Method.Method,
response != null ? (int) response.StatusCode : 500,
controller.InnerRequest.RequestUri.PathAndQuery,
sb != null ? sb.ToString() : null
);
}
catch (Exception e)
{
Logger.WarnException("Could not gather information to log request stats", e);
}
if (logHttpRequestStatsParam == null || sw == null)
return;
sw.Stop();
controller.MarkRequestDuration(sw.ElapsedMilliseconds);
LogHttpRequestStats(logHttpRequestStatsParam, controller.TenantName);
TraceRequest(logHttpRequestStatsParam, controller.TenantName);
}
private void LogHttpRequestStats(RavenBaseApiController controller, LogHttpRequestStatsParams logHttpRequestStatsParams, string databaseName, long curReq)
{
if (Logger.IsDebugEnabled == false)
return;
if (controller is StudioController || controller is HardRouteController || controller is SilverlightController)
return;
var message = string.Format(CultureInfo.InvariantCulture, "Request #{0,4:#,0}: {1,-7} - {2,5:#,0} ms - {5,-10} - {3} - {4}",
curReq,
logHttpRequestStatsParams.HttpMethod,
logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds,
logHttpRequestStatsParams.ResponseStatusCode,
logHttpRequestStatsParams.RequestUri,
databaseName);
Logger.Debug(message);
if (string.IsNullOrWhiteSpace(logHttpRequestStatsParams.CustomInfo) == false)
{
Logger.Debug(logHttpRequestStatsParams.CustomInfo);
}
}