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);
}
}
private void TraceTraffic(IResourceApiController controller, LogHttpRequestStatsParams logHttpRequestStatsParams, string resourceName, HttpResponseMessage response)
{
if (HasAnyHttpTraceEventTransport() == false)
{
return;
}
RavenJObject timingsJson = null;
if (controller is IndexController)
{
var jsonContent = response.Content as JsonContent;
if (jsonContent != null && jsonContent.Data != null)
{
timingsJson = jsonContent.Data.Value <RavenJObject>("TimingsInMilliseconds");
}
}
NotifyTrafficWatch(
string.IsNullOrEmpty(resourceName) == false ? resourceName : Constants.SystemDatabase,
new TrafficWatchNotification()
{
RequestUri = logHttpRequestStatsParams.RequestUri,
ElapsedMilliseconds = logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds,
CustomInfo = logHttpRequestStatsParams.CustomInfo,
HttpMethod = logHttpRequestStatsParams.HttpMethod,
ResponseStatusCode = logHttpRequestStatsParams.ResponseStatusCode,
TenantName = NormalizeTennantName(resourceName),
TimeStamp = SystemTime.UtcNow,
InnerRequestsCount = logHttpRequestStatsParams.InnerRequestsCount,
QueryTimings = timingsJson
}
);
}
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 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.ToString(),
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(controller, logHttpRequestStatsParam, controller.TenantName);
TraceRequest(logHttpRequestStatsParam, controller.TenantName);
}
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 TraceTraffic(RavenBaseApiController controller, LogHttpRequestStatsParams logHttpRequestStatsParams, string resourceName)
{
if (HasAnyHttpTraceEventTransport() == false)
{
return;
}
NotifyTrafficWatch(string.IsNullOrEmpty(resourceName) == false ? resourceName : Constants.SystemDatabase,
new TrafficWatchNotification()
{
RequestUri = logHttpRequestStatsParams.RequestUri,
ElapsedMilliseconds = logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds,
CustomInfo = logHttpRequestStatsParams.CustomInfo,
HttpMethod = logHttpRequestStatsParams.HttpMethod,
ResponseStatusCode = logHttpRequestStatsParams.ResponseStatusCode,
TenantName = NormalizeTennantName(resourceName),
TimeStamp = SystemTime.UtcNow,
InnerRequestsCount = logHttpRequestStatsParams.InnerRequestsCount
}
);
}
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
}
);
}
private void LogHttpRequestStats(LogHttpRequestStatsParams logHttpRequestStatsParams)
{
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,
currentTenantId.Value);
}
private void FinalizeRequestProcessing(IHttpContext ctx, Stopwatch sw, bool ravenUiRequest)
{
LogHttpRequestStatsParams logHttpRequestStatsParam = null;
try
{
logHttpRequestStatsParam = new LogHttpRequestStatsParams(
sw,
ctx.Request.Headers,
ctx.Request.HttpMethod,
ctx.Response.StatusCode,
ctx.Request.Url.PathAndQuery);
}
catch (Exception e)
{
logger.WarnException("Could not gather information to log request stats", e);
}
ctx.FinalizeResponse();
if (ravenUiRequest || logHttpRequestStatsParam == null || sw == null)
return;
sw.Stop();
LogHttpRequestStats(logHttpRequestStatsParam);
ctx.OutputSavedLogItems(logger);
}
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)
{
try
{
action(sb);
}
catch (Exception e)
{
Logger.WarnException("Could not gather information to log request stats custom info, so far got " + sb, e);
}
sb.AppendLine();
}
while (sb.Length > 0)
{
if (!char.IsWhiteSpace(sb[sb.Length - 1]))
{
break;
}
sb.Length--;
}
}
var innerRequest = controller.InnerRequest;
var httpRequestHeaders = innerRequest.Headers;
var httpContentHeaders = innerRequest.Content == null ? null : innerRequest.Content.Headers;
logHttpRequestStatsParam = new LogHttpRequestStatsParams(
sw,
new Lazy <HttpHeaders>(() => RavenBaseApiController.CloneRequestHttpHeaders(httpRequestHeaders, httpContentHeaders)),
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 FinalizeRequestProcessing(IResourceApiController 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)
{
try
{
action(sb);
}
catch (Exception e)
{
Logger.WarnException("Could not gather information to log request stats custom info, so far got " + sb, e);
}
sb.AppendLine();
}
while (sb.Length > 0)
{
if (!char.IsWhiteSpace(sb[sb.Length - 1]))
{
break;
}
sb.Length--;
}
}
var innerRequest = controller.InnerRequest;
var httpRequestHeaders = innerRequest.Headers;
var httpContentHeaders = innerRequest.Content == null ? null : innerRequest.Content.Headers;
logHttpRequestStatsParam = new LogHttpRequestStatsParams(
sw,
new Lazy <HttpHeaders>(() => RavenBaseApiController.CloneRequestHttpHeaders(httpRequestHeaders, httpContentHeaders)),
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();
MarkRequestDuration(controller, sw.ElapsedMilliseconds);
object requestNumber;
if (controller.InnerRequest.Properties.TryGetValue("requestNum", out requestNumber) && requestNumber is long)
{
LogHttpRequestStats(controller, logHttpRequestStatsParam, controller.ResourceName, (long)requestNumber);
}
if (controller.IsInternalRequest == false)
{
TraceTraffic(controller, logHttpRequestStatsParam, controller.ResourceName, response);
}
RememberRecentRequests(logHttpRequestStatsParam, controller.ResourceName);
}
private void LogHttpRequestStats(LogHttpRequestStatsParams logHttpRequestStatsParams)
{
// 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);
int idx = logHttpRequestStatsParams.RequestUri.IndexOf('?');
string ur = idx < 0 ? logHttpRequestStatsParams.RequestUri : logHttpRequestStatsParams.RequestUri.Substring(0, idx);
statLog.Info("{0}_{1}:{2}", logHttpRequestStatsParams.HttpMethod, ur, (int) logHttpRequestStatsParams.Stopwatch.ElapsedMilliseconds);
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,
currentTenantId.Value);
}
