microsoft/PowerPlatform-DataverseServiceClient

tokenProviderFunction doesn't work as expected.

heroes3lover opened this issue · 12 comments

In order to balance application users api call, we have 5 application users.
ServiceClient is initialized with bellow constructor
var client = new ServiceClient(new Uri(_authProvider.AuthDataConfiguration.Resource),_authProvider.GetBearerToken, false, _logger);
authProvider will cache the access token in concurrentdictionary
public async Task<string> GetBearerToken(string Resource) { var key = 0; bool locked = false; try { Monitor.TryEnter(_padlock, maxWaitForClientMs, ref locked); if (locked) { _currentIndex = (_currentIndex + 1) % AuthDataConfiguration.ClientCredentials.Count; key = _currentIndex; } } finally { if (locked) { Monitor.Exit(_padlock); } } if (!_tokenCache.TryGetValue(key, out var item) || item.ExpiresOn < DateTime.UtcNow.AddMinutes(5).ToUniversalTime()) { item = await RequestToken( AuthDataConfiguration.Authority, AuthDataConfiguration.Resource, AuthDataConfiguration.ClientCredentials[key]); _tokenCache.AddOrUpdate(key, item, (key, oldValue) => item); } _logger.LogDebug($"Index of bearer token is {key}"); _logger.LogDebug(item.AccessToken); return item.AccessToken; }

I sent 10 requests and from application log the token is provided evenly twice each.
But with Telerik Fillder these ten requests doesn't use those auth token evenly. only use 3 access tokens and count is 2,4,4

And because of that when I tested in staging environment with massive requests "Over 10000 limits" will appear in logs

I also tried another way, create 5 ServiceClient with different credentials and use them in turn, same result.
two credentials were heavily used and the other 3 credentials much less.

The client itself does not understand the threading scenario your using. In the scenario that you're using it in, how it's going to load balance is driven based on client instance you're using in each thread.

I would recommend taking a look at how the client is being selected for each thread

Thanks MattB,
It is nothing to do with thread, the ServiceClient factory is register as singleton and every D365 webapi call will apply for ServiceClient credentials via factory, factory will rotate the credentials to make sure it is absolute even.
We built this logic since crmsdk, from old dataverse analyst report the application users are used for nearly same count.

I have updated the sample code in github, Please follow bellow steps.

  • please provide multiple credentials in settings.
  • Start Telerik Fiddler
  • Run MultipleApiCall.exe
  • Compare the app.log and Fiddler log bearer token, you will see they are not matching( I mean count not sequence).

https://github.com/heroes3lover/MultipleApiCall/tree/users-mattb-variant1

Thank you very much.
This is critical issue for us, because even limit solved inside component by retrying, it will impact the caller and potential causes timeout. We need to try our best to make the call succeed at first place.

Looking at your code,
You're trying to change the auth token per request, this is not a great thing to do here... as its going to show up as incremental data being modified by different users on the same record. but its your choice. As long as all the accounts are identical permission wise, it will work.

I see your incrementor,
If your trying to counter check calls to get access token vis network traffic, your not going to be able to match them up directly as the ServiceClient will access the token as part of accessing its internal service references, not only when its going to make a call, this was the same behavior as CrmServiceClient.

We just ( as in last Friday) shipped an update to change the behavior of that to be a bit more controlled, reducing the times the service client asks for the token, though it still does not match up 100% with the request going out.

Hello Matt, thanks for the response.
These 5 credentials are created only for this app service, so it doesn't matter which one is applied, I think this business logic was built together with developers from Microsoft. The reason is the service is very busy and it can reach 23k requests in 5 minutes sometime.
Correct, I can see the ServiceClient will access the token as part of accessing its internal service references,
but after you run the MultipleApiCall.exe and check app.log, you will see the function tokenProviderFunction are called 10 times exactly same as requests count. nobody else request the token and rotate the incrementor.
2023-06-15 09:31:17.656 +10:00 [DBG] Index of bearer token is 2
2023-06-15 09:31:17.657 +10:00 [DBG] Index of bearer token is 3
2023-06-15 09:31:18.347 +10:00 [DBG] Index of bearer token is 4
2023-06-15 09:31:18.411 +10:00 [DBG] Index of bearer token is 0
2023-06-15 09:31:18.428 +10:00 [DBG] Index of bearer token is 1
2023-06-15 09:31:18.466 +10:00 [DBG] Index of bearer token is 2
2023-06-15 09:31:18.495 +10:00 [DBG] Index of bearer token is 3
2023-06-15 09:31:18.512 +10:00 [DBG] Index of bearer token is 4
2023-06-15 09:31:18.548 +10:00 [DBG] Index of bearer token is 0
2023-06-15 09:31:18.615 +10:00 [DBG] Index of bearer token is 1

but for those 10 "POST /XRMServices/2011/Organization.svc/web?SDKClientVersion=9.2.49.3165 HTTP/1.1",
I can see one token was used 3 times.
The only thing I can imagine is token of some Post requests are not using the token retrieved by calling tokenProviderFunction function. Correct me if I am wrong.
Not sure how much impacts, I will compile one version and deploy to staging for testing.
The dataverse analyst report will show the balance of usage of application users.

Thanks again for performance issue I raised before.
Since I use IOrganizationServiceAsync2 of 1.0.39, the performance looks pretty good in Staging environment now.
Since 1.1.9 CPU usage a bit higher, not sure if version related. sometime hits 69%.

Morning Matt, bellow is one day data, if token usage like that, I would say there will be so many over limits error in staging/Production. 5 credentials are the one with black dot in the front.

Balance
This is our current production(crmsdk), what is doing now is rotate the clientid and secret and create new crmclient for each request.

Surprised, I checked report for yesterday.
Balance

So the logic you wrote seems to be rotating the token used now?
if so,. lets close this one up.

thanks

Hello Matt, I will deploy to staging to see how it goes.
Staging is very busy one, the report will be more useful.
I will let you know the result.
Thanks for all the help.

Ok, im going to close this for now, Please reopen if there is something we can help you with.
Good luck with your rollout.