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(); } }