protected async Task <SampleAppResponse> SendGetRequestToSampleAppAndVerifyResponse(string relativeUrlPath, int expectedStatusCode,
bool timeHttpCall = true
)
{
var startTime = DateTime.UtcNow;
if (timeHttpCall)
{
_logger.Debug()
?.Log("HTTP call to sample application started at {Time} (as timestamp: {Timestamp})",
startTime, TimeUtils.ToTimestamp(startTime));
}
try
{
using (var httpClient = new HttpClient())
{
var response = await SendGetRequestToSampleAppAndVerifyResponseImpl(httpClient, relativeUrlPath, expectedStatusCode);
return(new SampleAppResponse(response.Headers, await response.Content.ReadAsStringAsync()));
}
}
finally
{
if (timeHttpCall)
{
_sampleAppClientCallTiming.Should().BeNull();
var endTime = DateTime.UtcNow;
_logger.Debug()
?.Log("HTTP call to sample application ended at {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
endTime, TimeUtils.ToTimestamp(endTime),
TimeUtils.DurationBetweenTimestamps(TimeUtils.ToTimestamp(startTime), TimeUtils.ToTimestamp(endTime)));
_sampleAppClientCallTiming = new TimedEvent(startTime, endTime);
}
}
}
public TimedEvent(DateTime start, DateTime end)
{
Timestamp = TimeUtils.ToTimestamp(start);
Duration = TimeUtils.DurationBetweenTimestamps(Timestamp, TimeUtils.ToTimestamp(end));
AssertValid();
}
public void End()
{
if (Duration.HasValue)
{
_logger.Trace()
?.Log("Ended {Span} (with Duration already set)." +
" Start time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp, Duration);
}
else
{
Assertion.IfEnabled?.That(!_isEnded,
$"Span's Duration doesn't have value even though {nameof(End)} method was already called." +
$" It contradicts the invariant enforced by {nameof(End)} method - Duration should have value when {nameof(End)} method exits" +
$" and {nameof(_isEnded)} field is set to true only when {nameof(End)} method exits." +
$" Context: this: {this}; {nameof(_isEnded)}: {_isEnded}");
var endTimestamp = TimeUtils.TimestampNow();
Duration = TimeUtils.DurationBetweenTimestamps(Timestamp, endTimestamp);
_logger.Trace()
?.Log("Ended {Span}. Start time: {Time} (as timestamp: {Timestamp})," +
" End time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp,
TimeUtils.FormatTimestampForLog(endTimestamp), endTimestamp, Duration);
}
var isFirstEndCall = !_isEnded;
_isEnded = true;
if (IsSampled && isFirstEndCall)
{
_payloadSender.QueueSpan(this);
}
}
public void End()
{
if (Duration.HasValue)
{
_logger.Trace()
?.Log("Ended {Span} (with Duration already set)." +
" Start time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp, Duration);
}
else
{
Assertion.IfEnabled?.That(!_isEnded,
$"Span's Duration doesn't have value even though {nameof(End)} method was already called." +
$" It contradicts the invariant enforced by {nameof(End)} method - Duration should have value when {nameof(End)} method exits" +
$" and {nameof(_isEnded)} field is set to true only when {nameof(End)} method exits." +
$" Context: this: {this}; {nameof(_isEnded)}: {_isEnded}");
var endTimestamp = TimeUtils.TimestampNow();
Duration = TimeUtils.DurationBetweenTimestamps(Timestamp, endTimestamp);
_logger.Trace()
?.Log("Ended {Span}. Start time: {Time} (as timestamp: {Timestamp})," +
" End time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp,
TimeUtils.FormatTimestampForLog(endTimestamp), endTimestamp, Duration);
}
var isFirstEndCall = !_isEnded;
_isEnded = true;
if (ShouldBeSentToApmServer && isFirstEndCall)
{
try
{
DeduceDestination();
}
catch (Exception e)
{
_logger.Warning()?.LogException(e, "Failed deducing destination fields for span.");
}
// Spans are sent only for sampled transactions so it's only worth capturing stack trace for sampled spans
// ReSharper disable once CompareOfFloatsByEqualityOperator
if (ConfigSnapshot.StackTraceLimit != 0 && ConfigSnapshot.SpanFramesMinDurationInMilliseconds != 0 && RawStackTrace == null &&
(Duration >= ConfigSnapshot.SpanFramesMinDurationInMilliseconds ||
ConfigSnapshot.SpanFramesMinDurationInMilliseconds < 0))
{
RawStackTrace = new StackTrace(true);
}
_payloadSender.QueueSpan(this);
}
if (isFirstEndCall)
{
_currentExecutionSegmentsContainer.CurrentSpan = _parentSpan;
}
}
public void End()
{
if (Duration.HasValue)
{
_logger.Trace()
?.Log("Ended {Span} (with Duration already set)." +
" Start time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp, Duration);
}
else
{
Assertion.IfEnabled?.That(!_isEnded,
$"Span's Duration doesn't have value even though {nameof(End)} method was already called." +
$" It contradicts the invariant enforced by {nameof(End)} method - Duration should have value when {nameof(End)} method exits" +
$" and {nameof(_isEnded)} field is set to true only when {nameof(End)} method exits." +
$" Context: this: {this}; {nameof(_isEnded)}: {_isEnded}");
var endTimestamp = TimeUtils.TimestampNow();
Duration = TimeUtils.DurationBetweenTimestamps(Timestamp, endTimestamp);
_logger.Trace()
?.Log("Ended {Span}. Start time: {Time} (as timestamp: {Timestamp})," +
" End time: {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
this, TimeUtils.FormatTimestampForLog(Timestamp), Timestamp,
TimeUtils.FormatTimestampForLog(endTimestamp), endTimestamp, Duration);
}
var isFirstEndCall = !_isEnded;
_isEnded = true;
if (!IsSampled || !isFirstEndCall)
{
return;
}
// Spans are sent only for sampled transactions so it's only worth capturing stack trace for sampled spans
// ReSharper disable once CompareOfFloatsByEqualityOperator
if (_configurationReader.StackTraceLimit != 0 && _configurationReader.SpanFramesMinDurationInMilliseconds != 0)
{
if (Duration >= _configurationReader.SpanFramesMinDurationInMilliseconds ||
_configurationReader.SpanFramesMinDurationInMilliseconds < 0)
{
StackTrace = StacktraceHelper.GenerateApmStackTrace(new StackTrace(true).GetFrames(), _logger,
_configurationReader, $"Span `{Name}'");
}
}
_payloadSender.QueueSpan(this);
_currentExecutionSegmentsContainer.CurrentSpan = _parentSpan;
}
protected async Task <SampleAppResponse> SendGetRequestToSampleAppAndVerifyResponse(string relativeUrlPath, int expectedStatusCode,
bool timeHttpCall = true, bool addTraceContextHeaders = false
)
{
var startTime = DateTime.UtcNow;
if (timeHttpCall)
{
_logger.Debug()
?.Log("HTTP call to sample application started at {Time} (as timestamp: {Timestamp})",
startTime, TimeUtils.ToTimestamp(startTime));
}
try
{
using (var httpClient = new HttpClient())
{
if (addTraceContextHeaders)
{
httpClient.DefaultRequestHeaders.Add("traceparent", "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01");
httpClient.DefaultRequestHeaders.Add("tracestate", "rojo=00f067aa0ba902b7,congo=t61rcWkgMzE");
}
var response = await SendGetRequestToSampleAppAndVerifyResponseImpl(httpClient, relativeUrlPath, expectedStatusCode);
return(new SampleAppResponse(response.Headers, await response.Content.ReadAsStringAsync()));
}
}
finally
{
if (timeHttpCall)
{
_sampleAppClientCallTiming.Should().BeNull();
var endTime = DateTime.UtcNow;
_logger.Debug()
?.Log("HTTP call to sample application ended at {Time} (as timestamp: {Timestamp}), Duration: {Duration}ms",
endTime, TimeUtils.ToTimestamp(endTime),
TimeUtils.DurationBetweenTimestamps(TimeUtils.ToTimestamp(startTime), TimeUtils.ToTimestamp(endTime)));
_sampleAppClientCallTiming = new TimedEvent(startTime, endTime);
}
}
}
private void IncrementDuration(long epochMicros) => Duration += TimeUtils.DurationBetweenTimestamps(_start, epochMicros);