private Task <TResult> OperationHelperWithRootTraceWithSynchronizationContextAsync <TResult>(
string operationName,
RequestOptions requestOptions,
Func <ITrace, Task <TResult> > task,
TraceComponent traceComponent,
Tracing.TraceLevel traceLevel)
{
Debug.Assert(SynchronizationContext.Current != null, "This should only be used when a SynchronizationContext is specified");
string syncContextVirtualAddress = SynchronizationContext.Current.ToString();
// Used on NETFX applications with SynchronizationContext when doing locking calls
return(Task.Run(async() =>
{
bool disableDiagnostics = requestOptions != null && requestOptions.DisablePointOperationDiagnostics;
using (ITrace trace = disableDiagnostics ? NoOpTrace.Singleton : (ITrace)Tracing.Trace.GetRootTrace(operationName, traceComponent, traceLevel))
{
trace.AddDatum("Synchronization Context", syncContextVirtualAddress);
return await this.RunWithDiagnosticsHelperAsync(
trace,
task);
}
}));
}
private ITrace CreateTestTraceTree()
{
ITrace trace;
using (trace = Trace.GetRootTrace("Root Trace", TraceComponent.Unknown, TraceLevel.Info))
{
using (ITrace firstLevel = trace.StartChild("First level Node", TraceComponent.Unknown, TraceLevel.Info))
{
using (ITrace secondLevel = firstLevel.StartChild("Second level Node", TraceComponent.Unknown, TraceLevel.Info))
{
using (ITrace thirdLevel = secondLevel.StartChild("Third level Node", TraceComponent.Unknown, TraceLevel.Info))
{
thirdLevel.AddDatum("Client Side Request Stats", this.GetDatumObject(Regions.CentralUS));
}
}
using (ITrace secondLevel = trace.StartChild("Second level Node", TraceComponent.Unknown, TraceLevel.Info))
{
secondLevel.AddDatum("Client Side Request Stats", this.GetDatumObject(Regions.CentralIndia, Regions.EastUS2));
}
}
using (ITrace firstLevel = trace.StartChild("First level Node", TraceComponent.Unknown, TraceLevel.Info))
{
firstLevel.AddDatum("Client Side Request Stats", this.GetDatumObject(Regions.FranceCentral));
}
}
return(trace);
}
public void DuplicateContactedReplicasTests()
{
ClientSideRequestStatisticsTraceDatum clientSideRequestStatisticsTraceDatum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow, new TraceSummary());
clientSideRequestStatisticsTraceDatum.ContactedReplicas.Add(new TransportAddressUri(new Uri("http://storephysicaladdress1.com")));
clientSideRequestStatisticsTraceDatum.ContactedReplicas.Add(new TransportAddressUri(new Uri("http://storephysicaladdress2.com")));
clientSideRequestStatisticsTraceDatum.ContactedReplicas.Add(new TransportAddressUri(new Uri("http://storephysicaladdress2.com")));
clientSideRequestStatisticsTraceDatum.ContactedReplicas.Add(new TransportAddressUri(new Uri("http://storephysicaladdress2.com")));
clientSideRequestStatisticsTraceDatum.ContactedReplicas.Add(new TransportAddressUri(new Uri("http://storephysicaladdress2.com")));
clientSideRequestStatisticsTraceDatum.ContactedReplicas.Add(new TransportAddressUri(new Uri("http://storephysicaladdress3.com")));
ITrace trace = Trace.GetRootTrace("test");
trace.AddDatum("stats", clientSideRequestStatisticsTraceDatum);
string json = new CosmosTraceDiagnostics(trace).ToString();
JObject jobject = JObject.Parse(json);
JToken contactedReplicas = jobject["data"]["stats"]["ContactedReplicas"];
Assert.AreEqual(3, contactedReplicas.Count());
int count = contactedReplicas[0]["Count"].Value <int>();
Assert.AreEqual(1, count);
string uri = contactedReplicas[0]["Uri"].Value <string>();
Assert.AreEqual("http://storephysicaladdress1.com/", uri);
count = contactedReplicas[1]["Count"].Value <int>();
Assert.AreEqual(4, count);
uri = contactedReplicas[1]["Uri"].Value <string>();
Assert.AreEqual("http://storephysicaladdress2.com/", uri);
count = contactedReplicas[2]["Count"].Value <int>();
Assert.AreEqual(1, count);
uri = contactedReplicas[2]["Uri"].Value <string>();
Assert.AreEqual("http://storephysicaladdress3.com/", uri);
}
private async Task <DocumentServiceResponse> ExecutePartitionKeyRangeReadChangeFeedAsync(string collectionRid,
INameValueCollection headers,
ITrace trace)
{
using (ITrace childTrace = trace.StartChild("Read PartitionKeyRange Change Feed", TraceComponent.Transport, Tracing.TraceLevel.Info))
{
using (DocumentServiceRequest request = DocumentServiceRequest.Create(
OperationType.ReadFeed,
collectionRid,
ResourceType.PartitionKeyRange,
AuthorizationTokenType.PrimaryMasterKey,
headers))
{
string authorizationToken = null;
try
{
authorizationToken = (await this.authorizationTokenProvider.GetUserAuthorizationAsync(
request.ResourceAddress,
PathsHelper.GetResourcePath(request.ResourceType),
HttpConstants.HttpMethods.Get,
request.Headers,
AuthorizationTokenType.PrimaryMasterKey)).token;
}
catch (UnauthorizedException)
{
}
if (authorizationToken == null)
{
// User doesn't have rid based resource token. Maybe he has name based.
throw new NotSupportedException("Resource tokens are not supported");
////CosmosContainerSettings collection = await this.collectionCache.ResolveCollectionAsync(request, CancellationToken.None);
////authorizationToken =
//// this.authorizationTokenProvider.GetUserAuthorizationTokenAsync(
//// collection.AltLink,
//// PathsHelper.GetResourcePath(request.ResourceType),
//// HttpConstants.HttpMethods.Get,
//// request.Headers,
//// AuthorizationTokenType.PrimaryMasterKey);
}
request.Headers[HttpConstants.HttpHeaders.Authorization] = authorizationToken;
using (new ActivityScope(Guid.NewGuid()))
{
try
{
return(await this.storeModel.ProcessMessageAsync(request));
}
catch (DocumentClientException ex)
{
childTrace.AddDatum("Exception Message", ex.Message);
throw;
}
}
}
}
}
internal async Task <ResponseMessage> ProcessMessageAsync(
RequestMessage request,
CancellationToken cancellationToken)
{
if (request == null)
{
throw new ArgumentNullException(nameof(request));
}
DocumentServiceRequest serviceRequest = request.ToDocumentServiceRequest();
ClientSideRequestStatisticsTraceDatum clientSideRequestStatisticsTraceDatum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow);
serviceRequest.RequestContext.ClientRequestStatistics = clientSideRequestStatisticsTraceDatum;
//TODO: extrace auth into a separate handler
string authorization = await((ICosmosAuthorizationTokenProvider)this.client.DocumentClient).GetUserAuthorizationTokenAsync(
serviceRequest.ResourceAddress,
PathsHelper.GetResourcePath(request.ResourceType),
request.Method.ToString(),
serviceRequest.Headers,
AuthorizationTokenType.PrimaryMasterKey,
request.Trace);
serviceRequest.Headers[HttpConstants.HttpHeaders.Authorization] = authorization;
IStoreModel storeProxy = this.client.DocumentClient.GetStoreProxy(serviceRequest);
using (ITrace processMessageAsyncTrace = request.Trace.StartChild(
name: $"{storeProxy.GetType().FullName} Transport Request",
component: TraceComponent.Transport,
level: Tracing.TraceLevel.Info))
{
request.Trace = processMessageAsyncTrace;
processMessageAsyncTrace.AddDatum("Client Side Request Stats", clientSideRequestStatisticsTraceDatum);
DocumentServiceResponse response = null;
try
{
response = request.OperationType == OperationType.Upsert
? await this.ProcessUpsertAsync(storeProxy, serviceRequest, cancellationToken)
: await storeProxy.ProcessMessageAsync(serviceRequest, cancellationToken);
}
finally
{
processMessageAsyncTrace.UpdateRegionContacted(clientSideRequestStatisticsTraceDatum);
}
return(response.ToCosmosResponseMessage(
request,
serviceRequest.RequestContext.RequestChargeTracker));
}
}
internal CosmosOperationCanceledException(
OperationCanceledException originalException,
ITrace trace)
{
this.originalException = originalException ?? throw new ArgumentNullException(nameof(originalException));
if (trace == null)
{
throw new ArgumentNullException(nameof(trace));
}
trace.AddDatum("Operation Cancelled Exception", originalException);
this.Diagnostics = new CosmosTraceDiagnostics(trace);
}
private async Task <ContainerProperties> ReadCollectionAsync(string collectionLink,
CancellationToken cancellationToken,
IDocumentClientRetryPolicy retryPolicyInstance,
ITrace trace)
{
using (ITrace childTrace = trace.StartChild("Read Collection", TraceComponent.Transport, TraceLevel.Info))
{
cancellationToken.ThrowIfCancellationRequested();
using (DocumentServiceRequest request = DocumentServiceRequest.Create(
OperationType.Read,
ResourceType.Collection,
collectionLink,
AuthorizationTokenType.PrimaryMasterKey,
new StoreRequestNameValueCollection()))
{
request.Headers[HttpConstants.HttpHeaders.XDate] = DateTime.UtcNow.ToString("r");
(string authorizationToken, string payload) = await this.tokenProvider.GetUserAuthorizationAsync(
request.ResourceAddress,
PathsHelper.GetResourcePath(request.ResourceType),
HttpConstants.HttpMethods.Get,
request.Headers,
AuthorizationTokenType.PrimaryMasterKey);
request.Headers[HttpConstants.HttpHeaders.Authorization] = authorizationToken;
using (new ActivityScope(Guid.NewGuid()))
{
if (retryPolicyInstance != null)
{
retryPolicyInstance.OnBeforeSendRequest(request);
}
try
{
using (DocumentServiceResponse response = await this.storeModel.ProcessMessageAsync(request))
{
return(CosmosResource.FromStream <ContainerProperties>(response));
}
}
catch (DocumentClientException ex)
{
childTrace.AddDatum("Exception Message", ex.Message);
throw;
}
}
}
}
}
public void RootTraceWithOneChildWithInfo()
{
Trace rootTrace;
using (rootTrace = Trace.GetRootTrace(name: "RootTrace"))
{
using (ITrace childTrace1 = rootTrace.StartChild("Child1"))
{
childTrace1.AddDatum("QueryMetrics", new QueryMetricsTraceDatum(MockQueryMetrics));
}
}
string traceString = TraceWriter.TraceToText(rootTrace);
}
private async ValueTask RefreshCachedTokenWithRetryHelperAsync(ITrace trace)
{
// A different thread is already updating the access token. Count starts off at 1.
bool skipRefreshBecause = this.backgroundRefreshLock.CurrentCount != 1;
await this.backgroundRefreshLock.WaitAsync();
try
{
// Token was already refreshed successfully from another thread.
if (skipRefreshBecause && this.cachedAccessToken.ExpiresOn > DateTime.UtcNow)
{
return;
}
Exception lastException = null;
const int totalRetryCount = 3;
for (int retry = 0; retry < totalRetryCount; retry++)
{
if (this.cancellationToken.IsCancellationRequested)
{
DefaultTrace.TraceInformation(
"Stop RefreshTokenWithIndefiniteRetries because cancellation is requested");
break;
}
using (ITrace getTokenTrace = trace.StartChild(
name: nameof(this.RefreshCachedTokenWithRetryHelperAsync),
component: TraceComponent.Authorization,
level: Tracing.TraceLevel.Info))
{
try
{
await this.ExecuteGetTokenWithRequestTimeoutAsync();
return;
}
catch (RequestFailedException requestFailedException)
{
lastException = requestFailedException;
getTokenTrace.AddDatum(
"Request Failed Exception",
new PointOperationStatisticsTraceDatum(
activityId: System.Diagnostics.Trace.CorrelationManager.ActivityId.ToString(),
statusCode: (HttpStatusCode)requestFailedException.Status,
subStatusCode: SubStatusCodes.Unknown,
responseTimeUtc: DateTime.UtcNow,
requestCharge: default,
internal CosmosOperationCanceledException(
OperationCanceledException originalException,
ITrace trace)
: base(originalException.CancellationToken)
{
this.originalException = originalException ?? throw new ArgumentNullException(nameof(originalException));
if (trace == null)
{
throw new ArgumentNullException(nameof(trace));
}
trace.AddDatum("Operation Cancelled Exception", originalException);
this.Diagnostics = new CosmosTraceDiagnostics(trace);
this.lazyMessage = this.CreateLazyMessage();
}
public static Task <PartitionedQueryExecutionInfo> GetQueryPlanThroughGatewayAsync(
CosmosQueryContext queryContext,
SqlQuerySpec sqlQuerySpec,
string resourceLink,
PartitionKey?partitionKey,
ITrace trace,
CancellationToken cancellationToken = default)
{
if (queryContext == null)
{
throw new ArgumentNullException(nameof(queryContext));
}
if (sqlQuerySpec == null)
{
throw new ArgumentNullException(nameof(sqlQuerySpec));
}
if (resourceLink == null)
{
throw new ArgumentNullException(nameof(resourceLink));
}
cancellationToken.ThrowIfCancellationRequested();
using (ITrace gatewayQueryPlanTrace = trace.StartChild("Gateway QueryPlan", TraceComponent.Query, TraceLevel.Info))
{
if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows) &&
Documents.ServiceInteropWrapper.Is64BitProcess)
{
// It's Windows and x64, should have loaded the DLL
gatewayQueryPlanTrace.AddDatum("ServiceInterop unavailable", true);
}
return(queryContext.ExecuteQueryPlanRequestAsync(
resourceLink,
ResourceType.Document,
OperationType.QueryPlan,
sqlQuerySpec,
partitionKey,
QueryPlanRetriever.SupportedQueryFeaturesString,
trace,
cancellationToken));
}
}
private async Task <TResult> OperationHelperWithRootTraceAsync <TResult>(
string operationName,
RequestOptions requestOptions,
Func <ITrace, Task <TResult> > task,
TraceComponent traceComponent,
Tracing.TraceLevel traceLevel)
{
bool disableDiagnostics = requestOptions != null && requestOptions.DisablePointOperationDiagnostics;
using (ITrace trace = disableDiagnostics ? NoOpTrace.Singleton : (ITrace)Tracing.Trace.GetRootTrace(operationName, traceComponent, traceLevel))
{
trace.AddDatum("Client Configuration", this.client.ClientConfigurationTraceDatum);
return(await this.RunWithDiagnosticsHelperAsync(
trace,
task));
}
}
public void ContactedRegionWithNameForClientTelemetryTest()
{
Trace trace;
using (trace = Trace.GetRootTrace("Root Trace", TraceComponent.Unknown, TraceLevel.Info))
{
using (ITrace firstLevel = trace.StartChild("First level Node", TraceComponent.Unknown, TraceLevel.Info))
{
firstLevel.AddDatum("Client Side Request Stats", this.GetDatumObject(Regions.FranceCentral));
}
}
CosmosDiagnostics diagnostics = new CosmosTraceDiagnostics(trace);
string regionsContacted = ClientTelemetryHelper.GetContactedRegions(diagnostics);
Assert.IsNotNull(regionsContacted);
Assert.AreEqual("France Central", regionsContacted);
}
internal CosmosOperationCanceledException(
OperationCanceledException originalException,
ITrace trace)
: base(originalException.CancellationToken)
{
this.originalException = originalException ?? throw new ArgumentNullException(nameof(originalException));
if (trace == null)
{
throw new ArgumentNullException(nameof(trace));
}
using (ITrace child = trace.StartChild("CosmosOperationCanceledException"))
{
child.AddDatum("Operation Cancelled Exception", originalException);
}
this.Diagnostics = new CosmosTraceDiagnostics(trace);
this.tokenCancellationRequested = originalException.CancellationToken.IsCancellationRequested;
this.toStringMessage = this.CreateToStringMessage();
this.lazyMessage = this.CreateLazyMessage();
}
public override async Task <ResponseMessage> ReadNextAsync(ITrace trace, CancellationToken cancellationToken)
{
if (trace == null)
{
throw new ArgumentNullException(nameof(trace));
}
// If Correlated Id already exists and is different, add a new one in comma separated list
// Scenario: A new iterator is created with same ContinuationToken and Trace
if (trace.Data.TryGetValue(QueryIterator.CorrelatedActivityIdKeyName, out object correlatedActivityIds))
{
List <string> correlatedIdList = correlatedActivityIds.ToString().Split(',').ToList();
if (!correlatedIdList.Contains(this.correlatedActivityId.ToString()))
{
correlatedIdList.Add(this.correlatedActivityId.ToString());
trace.AddOrUpdateDatum(QueryIterator.CorrelatedActivityIdKeyName,
string.Join(",", correlatedIdList));
}
}
else
{
trace.AddDatum(QueryIterator.CorrelatedActivityIdKeyName, this.correlatedActivityId.ToString());
}
TryCatch <QueryPage> tryGetQueryPage;
try
{
// This catches exception thrown by the pipeline and converts it to QueryResponse
this.queryPipelineStage.SetCancellationToken(cancellationToken);
if (!await this.queryPipelineStage.MoveNextAsync(trace))
{
this.hasMoreResults = false;
return(QueryResponse.CreateSuccess(
result: EmptyPage,
count: EmptyPage.Count,
responseLengthBytes: default,
internal async Task <ResponseMessage> ProcessMessageAsync(
RequestMessage request,
CancellationToken cancellationToken)
{
if (request == null)
{
throw new ArgumentNullException(nameof(request));
}
DocumentServiceRequest serviceRequest = request.ToDocumentServiceRequest();
ClientSideRequestStatisticsTraceDatum clientSideRequestStatisticsTraceDatum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow, request.Trace.Summary);
serviceRequest.RequestContext.ClientRequestStatistics = clientSideRequestStatisticsTraceDatum;
//TODO: extrace auth into a separate handler
string authorization = await((ICosmosAuthorizationTokenProvider)this.client.DocumentClient).GetUserAuthorizationTokenAsync(
serviceRequest.ResourceAddress,
PathsHelper.GetResourcePath(request.ResourceType),
request.Method.ToString(),
serviceRequest.Headers,
AuthorizationTokenType.PrimaryMasterKey,
request.Trace);
serviceRequest.Headers[HttpConstants.HttpHeaders.Authorization] = authorization;
IStoreModel storeProxy = this.client.DocumentClient.GetStoreProxy(serviceRequest);
using (ITrace processMessageAsyncTrace = request.Trace.StartChild(
name: $"{storeProxy.GetType().FullName} Transport Request",
component: TraceComponent.Transport,
level: Tracing.TraceLevel.Info))
{
request.Trace = processMessageAsyncTrace;
processMessageAsyncTrace.AddDatum("Client Side Request Stats", clientSideRequestStatisticsTraceDatum);
DocumentServiceResponse response = null;
try
{
response = await storeProxy.ProcessMessageAsync(serviceRequest, cancellationToken);
}
catch (DocumentClientException dce)
{
// Enrich diagnostics context in-case of auth failures
if (dce.StatusCode == System.Net.HttpStatusCode.Unauthorized || dce.StatusCode == System.Net.HttpStatusCode.Forbidden)
{
TimeSpan authProvideLifeSpan = this.client.DocumentClient.cosmosAuthorization.GetAge();
processMessageAsyncTrace.AddDatum("AuthProvider LifeSpan InSec", authProvideLifeSpan.TotalSeconds);
}
throw;
}
finally
{
processMessageAsyncTrace.UpdateRegionContacted(clientSideRequestStatisticsTraceDatum);
}
ResponseMessage responseMessage = response.ToCosmosResponseMessage(
request,
serviceRequest.RequestContext.RequestChargeTracker);
// Enrich diagnostics context in-case of auth failures
if (responseMessage?.StatusCode == System.Net.HttpStatusCode.Unauthorized || responseMessage?.StatusCode == System.Net.HttpStatusCode.Forbidden)
{
TimeSpan authProvideLifeSpan = this.client.DocumentClient.cosmosAuthorization.GetAge();
processMessageAsyncTrace.AddDatum("AuthProvider LifeSpan InSec", authProvideLifeSpan.TotalSeconds);
}
return(responseMessage);
}
}
private static TryCatch <QueryPage> GetCosmosElementResponse(
Guid clientQueryCorrelationId,
QueryRequestOptions requestOptions,
ResourceType resourceType,
ResponseMessage cosmosResponseMessage,
PartitionKeyRangeIdentity partitionKeyRangeIdentity,
Action <QueryPageDiagnostics> queryPageDiagnostics,
ITrace trace)
{
using (ITrace getCosmosElementResponse = trace.StartChild("Get Cosmos Element Response", TraceComponent.Json, Tracing.TraceLevel.Info))
{
using (cosmosResponseMessage)
{
QueryPageDiagnostics queryPage = new QueryPageDiagnostics(
clientQueryCorrelationId: clientQueryCorrelationId,
partitionKeyRangeId: partitionKeyRangeIdentity.PartitionKeyRangeId,
queryMetricText: cosmosResponseMessage.Headers.QueryMetricsText,
indexUtilizationText: cosmosResponseMessage.Headers[HttpConstants.HttpHeaders.IndexUtilization],
diagnosticsContext: cosmosResponseMessage.DiagnosticsContext);
queryPageDiagnostics(queryPage);
if (
cosmosResponseMessage.Headers.QueryMetricsText != null &&
BackendMetricsParser.TryParse(cosmosResponseMessage.Headers.QueryMetricsText, out BackendMetrics backendMetrics))
{
QueryMetricsTraceDatum datum = new QueryMetricsTraceDatum(
new QueryMetrics(backendMetrics, IndexUtilizationInfo.Empty, ClientSideMetrics.Empty));
trace.AddDatum("Query Metrics", datum);
}
if (!cosmosResponseMessage.IsSuccessStatusCode)
{
CosmosException exception;
if (cosmosResponseMessage.CosmosException != null)
{
exception = cosmosResponseMessage.CosmosException;
}
else
{
exception = new CosmosException(
cosmosResponseMessage.ErrorMessage,
cosmosResponseMessage.StatusCode,
(int)cosmosResponseMessage.Headers.SubStatusCode,
cosmosResponseMessage.Headers.ActivityId,
cosmosResponseMessage.Headers.RequestCharge);
}
return(TryCatch <QueryPage> .FromException(exception));
}
if (!(cosmosResponseMessage.Content is MemoryStream memoryStream))
{
memoryStream = new MemoryStream();
cosmosResponseMessage.Content.CopyTo(memoryStream);
}
long responseLengthBytes = memoryStream.Length;
CosmosArray documents = CosmosQueryClientCore.ParseElementsFromRestStream(
memoryStream,
resourceType,
requestOptions.CosmosSerializationFormatOptions);
CosmosQueryExecutionInfo cosmosQueryExecutionInfo;
if (cosmosResponseMessage.Headers.TryGetValue(QueryExecutionInfoHeader, out string queryExecutionInfoString))
{
cosmosQueryExecutionInfo = JsonConvert.DeserializeObject <CosmosQueryExecutionInfo>(queryExecutionInfoString);
}
else
{
cosmosQueryExecutionInfo = default;
}
QueryState queryState;
if (cosmosResponseMessage.Headers.ContinuationToken != null)
{
queryState = new QueryState(CosmosString.Create(cosmosResponseMessage.Headers.ContinuationToken));
}
else
{
queryState = default;
}
QueryPage response = new QueryPage(
documents,
cosmosResponseMessage.Headers.RequestCharge,
cosmosResponseMessage.Headers.ActivityId,
responseLengthBytes,
cosmosQueryExecutionInfo,
disallowContinuationTokenMessage: null,
queryState);
return(TryCatch <QueryPage> .FromResult(response));
}
}
}
public async Task MockQueryOutput()
{
CosmosClientSideRequestStatistics clientSideRequestStatistics = new CosmosClientSideRequestStatistics();
string id = clientSideRequestStatistics.RecordAddressResolutionStart(new Uri("https://testuri"));
clientSideRequestStatistics.RecordAddressResolutionEnd(id);
Documents.DocumentServiceRequest documentServiceRequest = new Documents.DocumentServiceRequest(
operationType: Documents.OperationType.Read,
resourceIdOrFullName: null,
resourceType: Documents.ResourceType.Database,
body: null,
headers: null,
isNameBased: false,
authorizationTokenType: Documents.AuthorizationTokenType.PrimaryMasterKey);
clientSideRequestStatistics.RecordRequest(documentServiceRequest);
clientSideRequestStatistics.RecordResponse(
documentServiceRequest,
new Documents.StoreResult(
storeResponse: new Documents.StoreResponse(),
exception: null,
partitionKeyRangeId: "PkRange",
lsn: 42,
quorumAckedLsn: 4242,
requestCharge: 9000.42,
currentReplicaSetSize: 3,
currentWriteQuorum: 4,
isValid: true,
storePhysicalAddress: null,
globalCommittedLSN: 2,
numberOfReadRegions: 1,
itemLSN: 5,
sessionToken: null,
usingLocalLSN: true,
activityId: Guid.NewGuid().ToString()));
Trace queryTrace;
using (queryTrace = Trace.GetRootTrace(
name: "Cross Partition Query",
component: TraceComponent.Query,
level: TraceLevel.Info))
{
using (ITrace getQueryPlanTrace = queryTrace.StartChild("GetQueryPlan"))
{
using (ITrace gatewayTrace = getQueryPlanTrace.StartChild(
"Gateway Call",
component: TraceComponent.Transport,
level: TraceLevel.Info))
{
Thread.Sleep(1);
gatewayTrace.AddDatum("ClientSideRequestStats", new CosmosDiagnosticsTraceDatum(clientSideRequestStatistics));
}
}
using (ITrace getPkRanges = queryTrace.StartChild("GetPkRanges"))
{
using (ITrace addressResolution = getPkRanges.StartChild(
"AddressResolution",
component: TraceComponent.Transport,
level: TraceLevel.Info))
{
await Task.Delay(1);
addressResolution.AddDatum("AddressResolutionStatistics", new CosmosDiagnosticsTraceDatum(
new AddressResolutionStatistics(
DateTime.MinValue,
DateTime.MinValue,
"https://testuri")));
}
}
using (ITrace queryPkRange1 = queryTrace.StartChild("Query PkRange 1"))
{
using (ITrace continuation1 = queryPkRange1.StartChild("Continuation 1"))
{
using (ITrace gatewayTrace = continuation1.StartChild(
"Execute Query Direct",
component: TraceComponent.Transport,
level: TraceLevel.Info))
{
await Task.Delay(1);
gatewayTrace.AddDatum("ClientSideRequestStats", new CosmosDiagnosticsTraceDatum(clientSideRequestStatistics));
}
continuation1.AddDatum("QueryMetrics", new QueryMetricsTraceDatum(MockQueryMetrics));
continuation1.AddDatum("RequestCharge", 42);
}
}
using (ITrace queryPkRange2 = queryTrace.StartChild("Query PkRange 2"))
{
using (ITrace continuation1 = queryPkRange2.StartChild("Continuation 1"))
{
using (ITrace gatewayTrace = continuation1.StartChild(
"Execute Query Direct",
component: TraceComponent.Transport,
level: TraceLevel.Info))
{
await Task.Delay(1);
gatewayTrace.AddDatum("ClientSideRequestStats", new CosmosDiagnosticsTraceDatum(clientSideRequestStatistics));
}
continuation1.AddDatum("QueryMetrics", new QueryMetricsTraceDatum(MockQueryMetrics));
continuation1.AddDatum("RequestCharge", 42);
}
using (ITrace continuation2 = queryPkRange2.StartChild("Continuation 2"))
{
using (ITrace gatewayTrace = continuation2.StartChild(
"Execute Query Direct",
component: TraceComponent.Transport,
level: TraceLevel.Info))
{
await Task.Delay(1);
gatewayTrace.AddDatum("ClientSideRequestStats", new CosmosDiagnosticsTraceDatum(clientSideRequestStatistics));
}
continuation2.AddDatum("QueryMetrics", new QueryMetricsTraceDatum(MockQueryMetrics));
continuation2.AddDatum("RequestCharge", 42);
}
}
}
string textTraceString = TraceWriter.TraceToText(queryTrace, asciiType: TraceWriter.AsciiType.DoubleLine);
string jsonTraceString = TraceWriter.TraceToJson(queryTrace);
}
private static TryCatch <QueryPage> GetCosmosElementResponse(
QueryRequestOptions requestOptions,
ResourceType resourceType,
ResponseMessage cosmosResponseMessage,
ITrace trace)
{
using (ITrace getCosmosElementResponse = trace.StartChild("Get Cosmos Element Response", TraceComponent.Json, Tracing.TraceLevel.Info))
{
using (cosmosResponseMessage)
{
if (
cosmosResponseMessage.Headers.QueryMetricsText != null &&
BackendMetricsParser.TryParse(cosmosResponseMessage.Headers.QueryMetricsText, out BackendMetrics backendMetrics))
{
QueryMetricsTraceDatum datum = new QueryMetricsTraceDatum(
new QueryMetrics(backendMetrics, IndexUtilizationInfo.Empty, ClientSideMetrics.Empty));
trace.AddDatum("Query Metrics", datum);
}
if (!cosmosResponseMessage.IsSuccessStatusCode)
{
CosmosException exception = cosmosResponseMessage.CosmosException ?? new CosmosException(
cosmosResponseMessage.ErrorMessage,
cosmosResponseMessage.StatusCode,
(int)cosmosResponseMessage.Headers.SubStatusCode,
cosmosResponseMessage.Headers.ActivityId,
cosmosResponseMessage.Headers.RequestCharge);
return(TryCatch <QueryPage> .FromException(exception));
}
if (!(cosmosResponseMessage.Content is MemoryStream memoryStream))
{
memoryStream = new MemoryStream();
cosmosResponseMessage.Content.CopyTo(memoryStream);
}
long responseLengthBytes = memoryStream.Length;
CosmosArray documents = CosmosQueryClientCore.ParseElementsFromRestStream(
memoryStream,
resourceType,
requestOptions.CosmosSerializationFormatOptions);
CosmosQueryExecutionInfo cosmosQueryExecutionInfo;
if (cosmosResponseMessage.Headers.TryGetValue(QueryExecutionInfoHeader, out string queryExecutionInfoString))
{
cosmosQueryExecutionInfo = JsonConvert.DeserializeObject <CosmosQueryExecutionInfo>(queryExecutionInfoString);
}
else
{
cosmosQueryExecutionInfo = default;
}
QueryState queryState;
if (cosmosResponseMessage.Headers.ContinuationToken != null)
{
queryState = new QueryState(CosmosString.Create(cosmosResponseMessage.Headers.ContinuationToken));
}
else
{
queryState = default;
}
Dictionary <string, string> additionalHeaders = new Dictionary <string, string>();
foreach (string key in cosmosResponseMessage.Headers)
{
if (!QueryPage.BannedHeaders.Contains(key))
{
additionalHeaders[key] = cosmosResponseMessage.Headers[key];
}
}
QueryPage response = new QueryPage(
documents,
cosmosResponseMessage.Headers.RequestCharge,
cosmosResponseMessage.Headers.ActivityId,
responseLengthBytes,
cosmosQueryExecutionInfo,
disallowContinuationTokenMessage: null,
additionalHeaders,
queryState);
return(TryCatch <QueryPage> .FromResult(response));
}
}
}
public void Serialization()
{
List <Input> inputs = new List <Input>();
int startLineNumber;
int endLineNumber;
//----------------------------------------------------------------
// Root Trace
//----------------------------------------------------------------
{
startLineNumber = GetLineNumber();
TraceForBaselineTesting rootTrace;
using (rootTrace = TraceForBaselineTesting.GetRootTrace())
{
}
endLineNumber = GetLineNumber();
inputs.Add(new Input("Root Trace", rootTrace, startLineNumber, endLineNumber));
}
//----------------------------------------------------------------
//----------------------------------------------------------------
// Root Trace With Datum
//----------------------------------------------------------------
{
startLineNumber = GetLineNumber();
TraceForBaselineTesting rootTraceWithDatum;
using (rootTraceWithDatum = TraceForBaselineTesting.GetRootTrace())
{
rootTraceWithDatum.AddDatum("QueryMetrics", new QueryMetricsTraceDatum(MockQueryMetrics));
}
endLineNumber = GetLineNumber();
inputs.Add(new Input("Root Trace With Datum", rootTraceWithDatum, startLineNumber, endLineNumber));
}
//----------------------------------------------------------------
//----------------------------------------------------------------
// Root Trace With One Child
//----------------------------------------------------------------
{
startLineNumber = GetLineNumber();
TraceForBaselineTesting rootTrace;
using (rootTrace = TraceForBaselineTesting.GetRootTrace())
{
using (ITrace childTrace1 = rootTrace.StartChild("Child1"))
{
}
}
endLineNumber = GetLineNumber();
inputs.Add(new Input("Root Trace With One Child", rootTrace, startLineNumber, endLineNumber));
}
//----------------------------------------------------------------
//----------------------------------------------------------------
// Root Trace With One Child With Datum
//----------------------------------------------------------------
{
startLineNumber = GetLineNumber();
TraceForBaselineTesting rootTrace;
using (rootTrace = TraceForBaselineTesting.GetRootTrace())
{
using (ITrace childTrace1 = rootTrace.StartChild("Child1"))
{
childTrace1.AddDatum("QueryMetrics", new QueryMetricsTraceDatum(MockQueryMetrics));
}
}
endLineNumber = GetLineNumber();
inputs.Add(new Input("Root Trace With One Child With Datum", rootTrace, startLineNumber, endLineNumber));
}
//----------------------------------------------------------------
//----------------------------------------------------------------
// Root Trace With Two Children
//----------------------------------------------------------------
{
startLineNumber = GetLineNumber();
TraceForBaselineTesting rootTrace;
using (rootTrace = TraceForBaselineTesting.GetRootTrace())
{
using (ITrace childTrace1 = rootTrace.StartChild("Child1"))
{
}
using (ITrace childTrace2 = rootTrace.StartChild("Child2"))
{
}
}
endLineNumber = GetLineNumber();
inputs.Add(new Input("Root Trace With Two Children", rootTrace, startLineNumber, endLineNumber));
}
//----------------------------------------------------------------
//----------------------------------------------------------------
// Root Trace With Two Children With Info
//----------------------------------------------------------------
{
startLineNumber = GetLineNumber();
TraceForBaselineTesting rootTrace;
using (rootTrace = TraceForBaselineTesting.GetRootTrace())
{
using (ITrace childTrace1 = rootTrace.StartChild("Child1"))
{
childTrace1.AddDatum("QueryMetrics", new QueryMetricsTraceDatum(MockQueryMetrics));
}
using (ITrace childTrace2 = rootTrace.StartChild("Child2"))
{
childTrace2.AddDatum("QueryMetrics", new QueryMetricsTraceDatum(MockQueryMetrics));
}
}
endLineNumber = GetLineNumber();
inputs.Add(new Input("Root Trace With Two Children With Info", rootTrace, startLineNumber, endLineNumber));
}
//----------------------------------------------------------------
//----------------------------------------------------------------
// Trace With Grandchidren
//----------------------------------------------------------------
{
startLineNumber = GetLineNumber();
TraceForBaselineTesting rootTrace;
using (rootTrace = TraceForBaselineTesting.GetRootTrace())
{
using (ITrace childTrace1 = rootTrace.StartChild(
name: "Child1",
component: TraceComponent.Unknown,
level: TraceLevel.Info))
{
using (ITrace child1Child1 = childTrace1.StartChild(
name: "Child1Child1",
component: TraceComponent.Unknown,
level: TraceLevel.Info))
{
}
using (ITrace child1Child2 = childTrace1.StartChild(
name: "Child1Child2",
component: TraceComponent.Unknown,
level: TraceLevel.Info))
{
}
}
using (ITrace childTrace2 = rootTrace.StartChild(
name: "Child2",
component: TraceComponent.Unknown,
level: TraceLevel.Info))
{
using (ITrace child2Child1 = childTrace2.StartChild(
name: "Child2Child1",
component: TraceComponent.Unknown,
level: TraceLevel.Info))
{
}
using (ITrace child2Child2 = childTrace2.StartChild(
name: "Child2Child2",
component: TraceComponent.Unknown,
level: TraceLevel.Info))
{
}
using (ITrace child2Child3 = childTrace2.StartChild(
name: "Child2Child3",
component: TraceComponent.Unknown,
level: TraceLevel.Info))
{
}
}
}
endLineNumber = GetLineNumber();
inputs.Add(new Input("Trace With Grandchildren", rootTrace, startLineNumber, endLineNumber));
}
//----------------------------------------------------------------
this.ExecuteTestSuite(inputs);
}
private async Task <HttpResponseMessage> SendHttpHelperAsync(
Func <ValueTask <HttpRequestMessage> > createRequestMessageAsync,
ResourceType resourceType,
HttpTimeoutPolicy timeoutPolicy,
ITrace trace,
CancellationToken cancellationToken)
{
DateTime startDateTimeUtc = DateTime.UtcNow;
IEnumerator <(TimeSpan requestTimeout, TimeSpan delayForNextRequest)> timeoutEnumerator = timeoutPolicy.GetTimeoutEnumerator();
timeoutEnumerator.MoveNext();
while (true)
{
cancellationToken.ThrowIfCancellationRequested();
(TimeSpan requestTimeout, TimeSpan delayForNextRequest) = timeoutEnumerator.Current;
using (HttpRequestMessage requestMessage = await createRequestMessageAsync())
{
// If the default cancellation token is passed then use the timeout policy
using CancellationTokenSource cancellationTokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken);
cancellationTokenSource.CancelAfter(requestTimeout);
using (ITrace helperTrace = trace.StartChild($"Execute Http With Timeout Policy: {timeoutPolicy.TimeoutPolicyName}", TraceComponent.Transport, Tracing.TraceLevel.Info))
{
try
{
return(await this.ExecuteHttpHelperAsync(
requestMessage,
resourceType,
cancellationTokenSource.Token));
}
catch (Exception e)
{
// Log the error message
trace.AddDatum(
"Error",
new PointOperationStatisticsTraceDatum(
activityId: System.Diagnostics.Trace.CorrelationManager.ActivityId.ToString(),
statusCode: HttpStatusCode.ServiceUnavailable,
subStatusCode: SubStatusCodes.Unknown,
responseTimeUtc: DateTime.UtcNow,
requestCharge: 0,
errorMessage: e.ToString(),
method: requestMessage.Method,
requestUri: requestMessage.RequestUri.OriginalString,
requestSessionToken: null,
responseSessionToken: null));
bool isOutOfRetries = (DateTime.UtcNow - startDateTimeUtc) > timeoutPolicy.MaximumRetryTimeLimit || // Maximum of time for all retries
!timeoutEnumerator.MoveNext(); // No more retries are configured
switch (e)
{
case OperationCanceledException operationCanceledException:
// Throw if the user passed in cancellation was requested
if (cancellationToken.IsCancellationRequested)
{
throw;
}
// Convert OperationCanceledException to 408 when the HTTP client throws it. This makes it clear that the
// the request timed out and was not user canceled operation.
if (isOutOfRetries || !timeoutPolicy.IsSafeToRetry(requestMessage.Method))
{
// throw timeout if the cancellationToken is not canceled (i.e. httpClient timed out)
string message =
$"GatewayStoreClient Request Timeout. Start Time UTC:{startDateTimeUtc}; Total Duration:{(DateTime.UtcNow - startDateTimeUtc).TotalMilliseconds} Ms; Request Timeout {requestTimeout.TotalMilliseconds} Ms; Http Client Timeout:{this.httpClient.Timeout.TotalMilliseconds} Ms; Activity id: {System.Diagnostics.Trace.CorrelationManager.ActivityId};";
throw CosmosExceptionFactory.CreateRequestTimeoutException(
message,
headers: new Headers()
{
ActivityId = System.Diagnostics.Trace.CorrelationManager.ActivityId.ToString()
},
innerException: operationCanceledException,
trace: helperTrace);
}
break;
case WebException webException:
if (isOutOfRetries || (!timeoutPolicy.IsSafeToRetry(requestMessage.Method) && !WebExceptionUtility.IsWebExceptionRetriable(webException)))
{
throw;
}
break;
case HttpRequestException httpRequestException:
if (isOutOfRetries || !timeoutPolicy.IsSafeToRetry(requestMessage.Method))
{
throw;
}
break;
default:
throw;
}
}
}
}
if (delayForNextRequest != TimeSpan.Zero)
{
using (ITrace delayTrace = trace.StartChild("Retry Delay", TraceComponent.Transport, Tracing.TraceLevel.Info))
{
await Task.Delay(delayForNextRequest);
}
}
}
}
private async Task <CollectionRoutingMap> GetRoutingMapForCollectionAsync(
string collectionRid,
CollectionRoutingMap previousRoutingMap,
ITrace trace,
IClientSideRequestStatistics clientSideRequestStatistics)
{
List <PartitionKeyRange> ranges = new List <PartitionKeyRange>();
string changeFeedNextIfNoneMatch = previousRoutingMap?.ChangeFeedNextIfNoneMatch;
HttpStatusCode lastStatusCode = HttpStatusCode.OK;
do
{
INameValueCollection headers = new RequestNameValueCollection();
headers.Set(HttpConstants.HttpHeaders.PageSize, PageSizeString);
headers.Set(HttpConstants.HttpHeaders.A_IM, HttpConstants.A_IMHeaderValues.IncrementalFeed);
if (changeFeedNextIfNoneMatch != null)
{
headers.Set(HttpConstants.HttpHeaders.IfNoneMatch, changeFeedNextIfNoneMatch);
}
RetryOptions retryOptions = new RetryOptions();
using (DocumentServiceResponse response = await BackoffRetryUtility <DocumentServiceResponse> .ExecuteAsync(
() => this.ExecutePartitionKeyRangeReadChangeFeedAsync(collectionRid, headers, trace, clientSideRequestStatistics),
new ResourceThrottleRetryPolicy(retryOptions.MaxRetryAttemptsOnThrottledRequests, retryOptions.MaxRetryWaitTimeInSeconds)))
{
lastStatusCode = response.StatusCode;
changeFeedNextIfNoneMatch = response.Headers[HttpConstants.HttpHeaders.ETag];
FeedResource <PartitionKeyRange> feedResource = response.GetResource <FeedResource <PartitionKeyRange> >();
if (feedResource != null)
{
ranges.AddRange(feedResource);
}
}
}while (lastStatusCode != HttpStatusCode.NotModified);
IEnumerable <Tuple <PartitionKeyRange, ServiceIdentity> > tuples = ranges.Select(range => Tuple.Create(range, (ServiceIdentity)null));
CollectionRoutingMap routingMap;
if (previousRoutingMap == null)
{
// Splits could have happened during change feed query and we might have a mix of gone and new ranges.
HashSet <string> goneRanges = new HashSet <string>(ranges.SelectMany(range => range.Parents ?? Enumerable.Empty <string>()));
routingMap = CollectionRoutingMap.TryCreateCompleteRoutingMap(
tuples.Where(tuple => !goneRanges.Contains(tuple.Item1.Id)),
string.Empty,
changeFeedNextIfNoneMatch);
}
else
{
routingMap = previousRoutingMap.TryCombine(tuples, changeFeedNextIfNoneMatch);
}
if (routingMap == null)
{
// Range information either doesn't exist or is not complete.
throw new NotFoundException($"{DateTime.UtcNow.ToString("o", CultureInfo.InvariantCulture)}: GetRoutingMapForCollectionAsync(collectionRid: {collectionRid}), Range information either doesn't exist or is not complete.");
}
trace.AddDatum($"PKRangeCache Info({DateTime.UtcNow.ToString("o", CultureInfo.InvariantCulture)})",
new PartitionKeyRangeCacheTraceDatum(
previousContinuationToken: previousRoutingMap?.ChangeFeedNextIfNoneMatch,
continuationToken: routingMap.ChangeFeedNextIfNoneMatch));
return(routingMap);
}
private async ValueTask RefreshCachedTokenWithRetryHelperAsync(ITrace trace)
{
// A different thread is already updating the access token. Count starts off at 1.
bool skipRefreshBecause = this.backgroundRefreshLock.CurrentCount != 1;
await this.backgroundRefreshLock.WaitAsync();
try
{
// Token was already refreshed successfully from another thread.
if (skipRefreshBecause && this.cachedAccessToken.ExpiresOn > DateTime.UtcNow)
{
return;
}
Exception lastException = null;
const int totalRetryCount = 3;
for (int retry = 0; retry < totalRetryCount; retry++)
{
if (this.cancellationToken.IsCancellationRequested)
{
DefaultTrace.TraceInformation(
"Stop RefreshTokenWithIndefiniteRetries because cancellation is requested");
break;
}
using (ITrace getTokenTrace = trace.StartChild(
name: nameof(this.RefreshCachedTokenWithRetryHelperAsync),
component: TraceComponent.Authorization,
level: Tracing.TraceLevel.Info))
{
try
{
await this.ExecuteGetTokenWithRequestTimeoutAsync();
return;
}
catch (RequestFailedException requestFailedException)
{
lastException = requestFailedException;
getTokenTrace.AddDatum(
$"RequestFailedException at {DateTime.UtcNow.ToString(CultureInfo.InvariantCulture)}",
requestFailedException);
DefaultTrace.TraceError($"TokenCredential.GetToken() failed with RequestFailedException. scope = {string.Join(";", this.tokenRequestContext.Scopes)}, retry = {retry}, Exception = {lastException}");
// Don't retry on auth failures
if (requestFailedException.Status == (int)HttpStatusCode.Unauthorized ||
requestFailedException.Status == (int)HttpStatusCode.Forbidden)
{
this.cachedAccessToken = default;
throw;
}
}
catch (OperationCanceledException operationCancelled)
{
lastException = operationCancelled;
getTokenTrace.AddDatum(
$"OperationCanceledException at {DateTime.UtcNow.ToString(CultureInfo.InvariantCulture)}",
operationCancelled);
DefaultTrace.TraceError(
$"TokenCredential.GetTokenAsync() failed. scope = {string.Join(";", this.tokenRequestContext.Scopes)}, retry = {retry}, Exception = {lastException}");
throw CosmosExceptionFactory.CreateRequestTimeoutException(
message: ClientResources.FailedToGetAadToken,
headers: new Headers()
{
SubStatusCode = SubStatusCodes.FailedToGetAadToken,
},
innerException: lastException,
trace: getTokenTrace);
}
catch (Exception exception)
{
lastException = exception;
getTokenTrace.AddDatum(
$"Exception at {DateTime.UtcNow.ToString(CultureInfo.InvariantCulture)}",
exception);
DefaultTrace.TraceError(
$"TokenCredential.GetTokenAsync() failed. scope = {string.Join(";", this.tokenRequestContext.Scopes)}, retry = {retry}, Exception = {lastException}");
}
}
DefaultTrace.TraceError(
$"TokenCredential.GetTokenAsync() failed. scope = {string.Join(";", this.tokenRequestContext.Scopes)}, retry = {retry}, Exception = {lastException}");
}
throw CosmosExceptionFactory.CreateUnauthorizedException(
message: ClientResources.FailedToGetAadToken,
headers: new Headers()
{
SubStatusCode = SubStatusCodes.FailedToGetAadToken,
},
innerException: lastException,
trace: trace);
}
finally
{
this.backgroundRefreshLock.Release();
}
}
