Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
Gareth064 opened this issue Oct 17, 2023 · 10 comments
Closed

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

Gareth064 opened this issue Oct 17, 2023 · 10 comments
Labels
Investigating We are looking into this issue at this time.

Comments

@Gareth064
Copy link

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
Copy link
Author

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
Copy link
Author

@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
Copy link
Author

Anyone able to help with this?

@MattB-msft
Copy link
Member

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

@Gareth064
Copy link
Author

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
Copy link
Member

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 MattB-msft added the Investigating We are looking into this issue at this time. label Dec 28, 2023
@MattB-msft
Copy link
Member

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

@MattB-msft
Copy link
Member

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

@Gareth064
Copy link
Author

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
Copy link
Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Investigating We are looking into this issue at this time.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@MattB-msft @Gareth064