private void LogHttpRequestStats(IResourceApiController 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);
if (Logger.IsDebugEnabled)
{
Logger.Debug(message);
}
if (Logger.IsDebugEnabled && 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 IncrementRequestNumberAndLog(IResourceApiController controller, HttpControllerContext controllerContext)
{
if (controller is StudioController || controller is HardRouteController || controller is SilverlightController)
{
return;
}
var curReq = Interlocked.Increment(ref reqNum);
controllerContext.Request.Properties["requestNum"] = curReq;
if (Logger.IsDebugEnabled)
{
Logger.Debug(string.Format(CultureInfo.InvariantCulture,
"Receive Request #{0,4:#,0}: {1,-7} - {2} - {3}",
curReq,
controller.InnerRequest.Method.Method,
controller.ResourceName,
controller.InnerRequest.RequestUri));
}
}
private void MarkRequestDuration(IResourceApiController controller, long elapsedMilliseconds)
{
switch (controller.ResourceType)
{
case ResourceType.Database:
if (landlord.IsDatabaseLoaded(controller.ResourceName ?? Constants.SystemDatabase))
{
controller.MarkRequestDuration(elapsedMilliseconds);
}
break;
case ResourceType.FileSystem:
break;
case ResourceType.TimeSeries:
break;
case ResourceType.Counter:
break;
default:
throw new NotSupportedException(controller.ResourceType.ToString());
}
}
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);
}
public async Task <HttpResponseMessage> HandleActualRequest(IResourceApiController controller,
HttpControllerContext controllerContext,
Func <Task <HttpResponseMessage> > action,
Func <HttpException, HttpResponseMessage> onHttpException)
{
HttpResponseMessage response = null;
cancellationToken.ThrowIfCancellationRequested();
Stopwatch sw = Stopwatch.StartNew();
try
{
LastRequestTime = SystemTime.UtcNow;
Interlocked.Increment(ref concurrentRequests);
IncrementRequestNumberAndLog(controller, controllerContext);
RequestWebApiEventArgs args = await controller.TrySetupRequestToProperResource().ConfigureAwait(false);
if (args != null)
{
OnBeforeRequest(args);
try
{
if (controllerContext.Request.Headers.Contains(Constants.RavenClientVersion))
{
if (controller.RejectClientRequests)
{
response = new HttpResponseMessage(HttpStatusCode.ServiceUnavailable)
{
Content = new MultiGetSafeStringContent("This service is not accepting clients calls")
};
}
else if (IsInHotSpareMode)
{
response = new HttpResponseMessage(HttpStatusCode.ServiceUnavailable)
{
Content = new MultiGetSafeStringContent("This service is not accepting clients calls because this is a 'Hot Spare' server")
};
}
else
{
response = await action().ConfigureAwait(false);
}
}
else
{
response = await action().ConfigureAwait(false);
}
}
finally
{
OnAfterRequest(args);
}
}
}
catch (HttpException httpException)
{
response = onHttpException(httpException);
}
finally
{
Interlocked.Decrement(ref concurrentRequests);
try
{
FinalizeRequestProcessing(controller, response, sw);
}
catch (Exception e)
{
var aggregateException = e as AggregateException;
if (aggregateException != null)
{
e = aggregateException.ExtractSingleInnerException();
}
Logger.ErrorException("Could not finalize request properly", e);
}
}
return(response);
}
