search

microsoft / PowerPlatform-DataverseServiceClient

Code Replica for Microsoft.PowerPlatform.Dataverse.Client and supporting nuget packages.
MIT License
281 stars 51 forks source link

System.NullReferenceException at Microsoft.PowerPlatform.Dataverse.Client.ServiceClient.Command_Execute #403

Closed Gareth064 closed 10 months ago

Gareth064 commented 1 year ago

Host: Azure Function App (Consumption) - HTTP Trigger Dotnet version: 6.00 SDK Version: 1.1.14

I upgraded my SDK from 0.6.1 to 1.1.14 last night.

Since doing so, I am getting exceptions being thrown which didn't happen on 0.6.1. (I know its a big jump in version)

************ NullReferenceException - RetrieveMultiple : RetrieveMultiple to Dataverse via IOrganizationService |=> Object reference not set to an instance of an object.
Source: Microsoft.PowerPlatform.Dataverse.Client
Method: Command_Execute
DateUTC: 10/17/2023
TimeUTC: 9:42:36 AM
Error: Object reference not set to an instance of an object.
HelpLink Url: Not Provided
Stack Trace: at Microsoft.PowerPlatform.Dataverse.Client.ServiceClient.Command_Execute(OrganizationRequest req, String errorStringCheck, Boolean bypassPluginExecution)
======================================================================================================================
Microsoft.Azure.WebJobs.Host.FunctionInvocationException:
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithLoggingAsync>d__26.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.39.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:352)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<TryExecuteAsync>d__18.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.39.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:108)
Inner exception System.NullReferenceException handled at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw:
   at Microsoft.PowerPlatform.Dataverse.Client.ServiceClient+<RetrieveMultipleAsync>d__180.MoveNext (Microsoft.PowerPlatform.Dataverse.Client, Version=1.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.PowerPlatform.Dataverse.Client.ServiceClient+<RetrieveMultipleAsync>d__170.MoveNext (Microsoft.PowerPlatform.Dataverse.Client, Version=1.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at CHG.DFS.DDB.Functions.OrganisationServiceAdapter+<RetrieveMultipleAsync>d__6.MoveNext (CHG.DFS.DDB.Functions, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: D:\a\1\s\CHG.DFS.DDB.Functions\Providers\OrganisationServiceAdapter.cs:42)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at CHG.DFS.DDB.Functions.FieldServicesDataProvider+<GetEntities>d__28.MoveNext (CHG.DFS.DDB.Functions, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: D:\a\1\s\CHG.DFS.DDB.Functions\Providers\FieldServicesDataProvider.cs:627)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at CHG.DFS.DDB.Functions.FieldServicesDataProvider+<ExecuteWorkOrderQuery>d__16.MoveNext (CHG.DFS.DDB.Functions, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: D:\a\1\s\CHG.DFS.DDB.Functions\Providers\FieldServicesDataProvider.cs:284)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at CHG.DFS.DDB.Functions.FieldServicesDataProvider+<GetWorkOrder>d__15.MoveNext (CHG.DFS.DDB.Functions, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: D:\a\1\s\CHG.DFS.DDB.Functions\Providers\FieldServicesDataProvider.cs:277)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at CHG.DFS.DDB.Functions.IntegrationProvider+<IntegrateWorkOrder>d__4.MoveNext (CHG.DFS.DDB.Functions, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: D:\a\1\s\CHG.DFS.DDB.Functions\Providers\IntegrationProvider.cs:37)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at CHG.DFS.DDB.Functions.FieldServicesFunctions+<WorkOrder>d__8.MoveNext (CHG.DFS.DDB.Functions, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null: D:\a\1\s\CHG.DFS.DDB.Functions\FieldServicesFunctions.cs:83)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionInvoker`2+<InvokeAsync>d__10.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.39.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionInvoker.cs:52)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<InvokeWithTimeoutAsync>d__33.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.39.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:581)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithWatchersAsync>d__32.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.39.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:527)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithLoggingAsync>d__26.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.39.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35: D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:306)

This is a function app which runs at a pretty high volume to sync records between Dataverse and a SQL database. Daily volumes are roughly 90k requests per day, with the higher portion of those happening between 8am and 6pm.

I can't replicate it in a non-prod environment at the moment so I attached a debugger to the production instance running in Azure.

Here is a screenshot of where it throws the exception each time

image

This is how I am registering the ServiceClient in DI

builder.Services.AddScoped<IOrganizationServiceAsync2>((s) =>
{
    logger = s.GetService<ILogger<Startup>>()!;

    IOrganizationServiceAsync2 serviceClient;

    try
    {
        var appUri = new Uri(appD365Environment!);
        serviceClient = new ServiceClient(appUri, appD365ClientId, appD365ClientSecret, false, logger);
    }
    catch (Exception e)
    {
        logger.LogError($@"Issues encountered during configuration - {e.Message}");

        throw;
    }

    return serviceClient;
});

Then its used like so

public class OrganisationServiceAdapter : IOrganisationServiceAdapter
{
    private readonly IOrganizationServiceAsync2 client;

    public OrganisationServiceAdapter(IOrganizationServiceAsync2 client)
    {
        this.client = client ?? throw new ArgumentNullException(nameof(client));
    }

    public string ConnectedOrgFriendlyName
    {
        get { return ((ServiceClient)client).ConnectedOrgFriendlyName; }
    }

    public AttributeMetadata GetEntityAttributeMetadataForAttribute(string entity, string name)
    {
        return ((ServiceClient)client).GetEntityAttributeMetadataForAttribute(entity, name);
    }

    public OptionSetMetadata GetGlobalOptionSetMetadata(string name)
    {
        return ((ServiceClient)client).GetGlobalOptionSetMetadata(name);
    }

    public async Task<EntityCollection> RetrieveMultipleAsync(QueryExpression qe)
    {
        return await ((ServiceClient)client).RetrieveMultipleAsync(qe);
    }
}

It is throwing these errors when I use the RetrieveMultipleAsync method it seems.

Trace Logs from app insights make me believe the connection is created fine because before we start making any calls, we log which Organization we are connected to. And that trace log is present every time.

To be clear, this is intermittent. in the past 20 hours (since it was updated) this function app has handled 78k requests, with 381 of these failing with the above error.

I am putting my money on something to do with how I am creating the ServiceClient on a per request basis?

I did notice that the SDK method it throws from is called Execute_Command which doesn't appear to be async. Where there is a version of it which is async Execute_CommandAsync

Has anyone got any ideas?

Gareth064 commented 1 year ago

I just attached the bugger again and when it hits the exception, inside the ServiceClient class, the "Details" are only showing this

System.NullReferenceException
  HResult=0x80004003
  Message=Object reference not set to an instance of an object.
  Source=Microsoft.PowerPlatform.Dataverse.Client
  StackTrace:
   at Microsoft.PowerPlatform.Dataverse.Client.ServiceClient.Command_Execute(OrganizationRequest req, String errorStringCheck, Boolean bypassPluginExecution) in Microsoft.PowerPlatform.Dataverse.Client\ServiceClient.cs:line 1299
Gareth064 commented 1 year ago

@MattB-msft sorry to tag you directly, but you appear to answer a lot of the issues and discussions on here. My management are asking me to rollback the upgrade if I can't figure this out in the next 24 hours :(

Would you be able to provide feedback on this issue?

Gareth064 commented 1 year ago

Anyone able to help with this?

MattB-msft commented 1 year ago

We are taking a look at this now.. sorry for the delay... the team has been very busy with a number of projects.

Gareth064 commented 12 months ago

Thank you @MattB-msft. I had to beef up my resilience layer in my code to implement better retries. The request works a second time.

This appears to be very intermittent. But enough that we come into work each day with hundreds of errors logged related to this.

MattB-msft commented 10 months ago

Thanks for this... we have been having a heck of a time trying to run this down.

I wonder if this is a 'hardware' clock issue.. StopWatch is a low level handler.. see : https://learn.microsoft.com/en-us/dotnet/api/system.diagnostics.stopwatch?view=net-8.0#remarks

Im going to have the team put in a speculative fix here to see if that resolves it.

MattB-msft commented 10 months ago

We have included the speculative fix in 1.1.17 and are going to close this issue...if it resurfaces, please reopen.

MattB-msft commented 10 months ago

linking to https://github.com/microsoft/PowerPlatform-DataverseServiceClient/releases/tag/1.1.17

Gareth064 commented 7 months ago

Hi @MattB-msft , I finally got around to trying 1.1.17

Unfortunately it hasn't worked out well.

Here what I've done.

Whilst still on v1.1.14, I sent 1000 sequential requests to the function app (that hosts the code using the SDK) and it handled all 1000 fine.

I upgrade the SDK to 1.1.17 and sent 1000 sequential requests again.

After 252 successful requests, the function app appears to have died/shutdown as I started to get a response saying "Function host is not running."

The next 171 requests continued to get the same "Function host is not running." response.

After the function app appeared to come back online again, the final 577 requests failed with the following error returned from the SDK

Unable to connect to Dataverse: Unable to cast object of type 'generatedProxy_2' to type 'Microsoft.PowerPlatform.Dataverse.Client.IOrganizationServiceAsync'.
Source: System.Private.CoreLib
Method: ChkCastAny
DateUTC: 4/10/2024
TimeUTC: 3:44:18 PM
Error: Unable to cast object of type 'generatedProxy_2' to type 'Microsoft.PowerPlatform.Dataverse.Client.IOrganizationServiceAsync'.
HelpLink Url: Not Provided
Stack Trace: at System.Reflection.DispatchProxy.Create[T,TProxy]()
   at System.ServiceModel.Channels.ServiceChannelProxy.CreateProxy[TChannel](MessageDirection direction, ServiceChannel serviceChannel)
   at System.ServiceModel.Channels.ServiceChannelFactory.CreateProxy[TChannel](MessageDirection direction, ServiceChannel serviceChannel)
   at System.ServiceModel.Channels.ServiceChannelFactory.CreateChannel[TChannel](EndpointAddress address, Uri via)
   at System.ServiceModel.ChannelFactory`1.CreateChannel(EndpointAddress address, Uri via)
   at System.ServiceModel.ChannelFactory`1.CreateChannel()
   at System.ServiceModel.ClientBase`1.CreateChannel()
   at System.ServiceModel.ClientBase`1.CreateChannelInternal()
   at System.ServiceModel.ClientBase`1.get_Channel()
   at System.ServiceModel.ClientBase`1.get_InnerChannel()
   at Microsoft.PowerPlatform.Dataverse.Client.ConnectionService.ConnectAndInitServiceAsync(OrganizationDetail orgdata, Boolean IsOnPrem, Uri homeRealmUri)
   at Microsoft.PowerPlatform.Dataverse.Client.ConnectionService.DoDirectLoginAsync(Boolean IsOnPrem)
   at Microsoft.PowerPlatform.Dataverse.Client.ConnectionService.InitServiceAsync()
======================================================================================================================

A few questions

  1. I feel like I used to see the same error message when running the older SDK 0.6.1. Is this a regression?
  2. This is a consumption function app. Do you think it isn't the right hosting model for something that might be making lots of connections to the Dataverse in quick succession?
  3. In my original post I explained how I am making the connections to the Dataverse via a Startup class, is there anything I could be doing differently there to help elevate connection creation issues?
Gareth064 commented 6 months ago

Regarding my previous message, to get passed it, I changed from a Scoped service to a Singleton service in my startup class and it has allowed high volume requests to go through without issue.

Back to the original issue, I can confirm that this error is no longer happening. It has been live in production for 3 days now and no occurrence has happened, where previously there were hundreds of exceptions daily.