microsoft
NullReferenceException instead of real exception
Sometimes, somehow, ExecuteOrganizationRequestImpl returns null without setting LastException.
https://github.com/microsoft/PowerPlatform-DataverseServiceClient/blob/254952f3a781f1ab363c56f1a43c4d9b49652fed/src/GeneralTools/DataverseClient/Client/ServiceClient.cs#L1969-L1971
This leads to a NullReferenceException instead of the real error, which is very confusing.
Verified in 0.5.17 and 0.6.1.
Here's an example of log output in such a case:
[2022-04-12T19:26:07.625Z] Failure Response for request to WebAPI Patch /api/data/v9.2/dpac_corbackgroundprocesses(0eb423f7-95ba-ec11-983f-00224818ca30) : StatusCode=PreconditionFailed : SessionID=83435ab3-2591-44ad-a35f-ab432372ca2a : RequestID=5b21aead-8ef9-464c-bc31-8dfafbd6d5f7 : {"error":{"code":"0x80060882","message":"The version of the existing record doesn't match the RowVersion property provided.","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionSourceKey":"Plugin/Microsoft.Crm.ObjectModel.CustomBusinessEntityService","@Microsoft.PowerApps.CDS.ErrorDetails.ApiStepKey":"e6c06e5a-4903-ec11-b6e5-00224817ffe1","@Microsoft.PowerApps.CDS.ErrorDetails.ApiDepthKey":"1","@Microsoft.PowerApps.CDS.ErrorDetails.ApiActivityIdKey":"fd019a5f-a929-4d74-9f0a-f8c6b6d365e6","@Microsoft.PowerApps.CDS.ErrorDetails.ApiPluginSolutionNameKey":"System","@Microsoft.PowerApps.CDS.ErrorDetails.ApiStepSolutionNameKey":"System","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionCategory":"ClientError","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionMessageName":"ConcurrencyVersionMismatch","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionHttpStatusCode":"412","@Microsoft.PowerApps.CDS.HelpLink":"http://go.microsoft.com/fwlink/?LinkID=398563&error=Microsoft.Crm.CrmException%3a80060882&client=platform","@Microsoft.PowerApps.CDS.InnerError.Message":"The version of the existing record doesn't match the RowVersion property provided."}}
[2022-04-12T19:26:07.636Z] Source: Not Provided
[2022-04-12T19:26:07.639Z] Method: Not Provided
[2022-04-12T19:26:07.641Z] DateUTC: 12/04/2022
[2022-04-12T19:26:07.644Z] TimeUTC: 7:26:07 PM
[2022-04-12T19:26:07.656Z] Error: Failure Response for request to WebAPI Patch /api/data/v9.2/dpac_corbackgroundprocesses(0eb423f7-95ba-ec11-983f-00224818ca30) : StatusCode=PreconditionFailed : SessionID=83435ab3-2591-44ad-a35f-ab432372ca2a : RequestID=5b21aead-8ef9-464c-bc31-8dfafbd6d5f7 : {"error":{"code":"0x80060882","message":"The version of the existing record doesn't match the RowVersion property provided.","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionSourceKey":"Plugin/Microsoft.Crm.ObjectModel.CustomBusinessEntityService","@Microsoft.PowerApps.CDS.ErrorDetails.ApiStepKey":"e6c06e5a-4903-ec11-b6e5-00224817ffe1","@Microsoft.PowerApps.CDS.ErrorDetails.ApiDepthKey":"1","@Microsoft.PowerApps.CDS.ErrorDetails.ApiActivityIdKey":"fd019a5f-a929-4d74-9f0a-f8c6b6d365e6","@Microsoft.PowerApps.CDS.ErrorDetails.ApiPluginSolutionNameKey":"System","@Microsoft.PowerApps.CDS.ErrorDetails.ApiStepSolutionNameKey":"System","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionCategory":"ClientError","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionMessageName":"ConcurrencyVersionMismatch","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionHttpStatusCode":"412","@Microsoft.PowerApps.CDS.HelpLink":"http://go.microsoft.com/fwlink/?LinkID=398563&error=Microsoft.Crm.CrmException%3a80060882&client=platform","@Microsoft.PowerApps.CDS.InnerError.Message":"The version of the existing record doesn't match the RowVersion property provided."}}
[2022-04-12T19:26:07.669Z] HelpLink Url: Not Provided
[2022-04-12T19:26:07.671Z] Stack Trace: Not Provided
[2022-04-12T19:26:07.674Z] ======================================================================================================================
[2022-04-12T19:26:07.676Z]
[2022-04-12T19:26:07.681Z] Failure Response for request to WebAPI Patch /api/data/v9.2/dpac_corbackgroundprocesses(0eb423f7-95ba-ec11-983f-00224818ca30) : StatusCode=PreconditionFailed : SessionID=83435ab3-2591-44ad-a35f-ab432372ca2a : RequestID=5b21aead-8ef9-464c-bc31-8dfafbd6d5f7 : {"error":{"code":"0x80060882","message":"The version of the existing record doesn't match the RowVersion property provided.","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionSourceKey":"Plugin/Microsoft.Crm.ObjectModel.CustomBusinessEntityService","@Microsoft.PowerApps.CDS.ErrorDetails.ApiStepKey":"e6c06e5a-4903-ec11-b6e5-00224817ffe1","@Microsoft.PowerApps.CDS.ErrorDetails.ApiDepthKey":"1","@Microsoft.PowerApps.CDS.ErrorDetails.ApiActivityIdKey":"fd019a5f-a929-4d74-9f0a-f8c6b6d365e6","@Microsoft.PowerApps.CDS.ErrorDetails.ApiPluginSolutionNameKey":"System","@Microsoft.PowerApps.CDS.ErrorDetails.ApiStepSolutionNameKey":"System","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionCategory":"ClientError","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionMessageName":"ConcurrencyVersionMismatch","@Microsoft.PowerApps.CDS.ErrorDetails.ApiExceptionHttpStatusCode":"412","@Microsoft.PowerApps.CDS.HelpLink":"http://go.microsoft.com/fwlink/?LinkID=398563&error=Microsoft.Crm.CrmException%3a80060882&client=platform","@Microsoft.PowerApps.CDS.InnerError.Message":"The version of the existing record doesn't match the RowVersion property provided."}}.
[2022-04-12T19:26:07.738Z] ************ HttpOperationException - Patch dpac_corbackgroundprocesses(0eb423f7-95ba-ec11-983f-00224818ca30) : Execute (Update) request to Dataverse from IOrganizationService |=> The version of the existing record doesn't match the RowVersion property provided.
[2022-04-12T19:26:07.742Z] ==DataverseOperationException Info=======================================================================================
[2022-04-12T19:26:07.744Z] Source: Dataverse Server API
[2022-04-12T19:26:07.746Z] Error: The version of the existing record doesn't match the RowVersion property provided.
[2022-04-12T19:26:07.747Z] ErrorCode: -2147088254
[2022-04-12T19:26:07.749Z] DateUTC: 12/04/2022
[2022-04-12T19:26:07.750Z] TimeUTC: 7:26:07 PM
[2022-04-12T19:26:07.752Z] HelpLink Url: http://go.microsoft.com/fwlink/?LinkID=398563&error=Microsoft.Crm.CrmException%3a80060882&client=platform
[2022-04-12T19:26:07.753Z] DataverseErrorDetail:
[2022-04-12T19:26:07.755Z] ApiExceptionSourceKey: Plugin/Microsoft.Crm.ObjectModel.CustomBusinessEntityService
[2022-04-12T19:26:07.761Z] ApiStepKey: e6c06e5a-4903-ec11-b6e5-00224817ffe1
[2022-04-12T19:26:07.762Z] ApiDepthKey: 1
[2022-04-12T19:26:07.764Z] ApiActivityIdKey: fd019a5f-a929-4d74-9f0a-f8c6b6d365e6
[2022-04-12T19:26:07.766Z] ApiPluginSolutionNameKey: System
[2022-04-12T19:26:07.767Z] ApiStepSolutionNameKey: System
[2022-04-12T19:26:07.769Z] ApiExceptionCategory: ClientError
[2022-04-12T19:26:07.770Z] ApiExceptionMessageName: ConcurrencyVersionMismatch
[2022-04-12T19:26:07.775Z] ApiExceptionHttpStatusCode: 412
[2022-04-12T19:26:07.779Z] ======================================================================================================================
[2022-04-12T19:26:07.781Z] Inner Exception Level 1 :
[2022-04-12T19:26:07.783Z] Source: Microsoft.PowerPlatform.Dataverse.Client
[2022-04-12T19:26:07.786Z] Method: MoveNext
[2022-04-12T19:26:07.792Z] DateUTC: 12/04/2022
[2022-04-12T19:26:07.793Z] TimeUTC: 7:26:07 PM
[2022-04-12T19:26:07.797Z] Error: Message: The version of the existing record doesn't match the RowVersion property provided.
ActivityId: 641ade70-0a7a-485d-ab33-ee057037f689
[2022-04-12T19:26:07.801Z] HelpLink Url: Not Provided
[2022-04-12T19:26:07.803Z] Stack Trace: Not Provided
[2022-04-12T19:26:07.808Z] ======================================================================================================================
[2022-04-12T19:26:07.811Z]
[2022-04-12T19:26:07.812Z] Dataverse Server API: The version of the existing record doesn't match the RowVersion property provided. Microsoft.PowerPlatform.Dataverse.Client: Operation returned an invalid status code 'PreconditionFailed'.
[2022-04-12T19:26:07.816Z] [TerminalFailure] Failed to Execute Command - Patch dpac_corbackgroundprocesses(0eb423f7-95ba-ec11-983f-00224818ca30) : SessionID=83435ab3-2591-44ad-a35f-ab432372ca2a : RequestID=5b21aead-8ef9-464c-bc31-8dfafbd6d5f7 : Execute (Update) request to Dataverse from IOrganizationService duration=00:00:00.7709414 ExceptionMessage = The version of the existing record doesn't match the RowVersion property provided.
[2022-04-12T19:26:07.825Z] Source: Microsoft.PowerPlatform.Dataverse.Client
[2022-04-12T19:26:07.828Z] Method: MoveNext
[2022-04-12T19:26:07.830Z] DateUTC: 12/04/2022
[2022-04-12T19:26:07.832Z] TimeUTC: 7:26:07 PM
[2022-04-12T19:26:07.833Z] Error: Message: The version of the existing record doesn't match the RowVersion property provided.
ActivityId: 641ade70-0a7a-485d-ab33-ee057037f689
[2022-04-12T19:26:07.838Z] HelpLink Url: Not Provided
[2022-04-12T19:26:07.842Z] Stack Trace: Not Provided
[2022-04-12T19:26:07.844Z] ======================================================================================================================
[2022-04-12T19:26:07.846Z]
[2022-04-12T19:26:07.849Z] Microsoft.PowerPlatform.Dataverse.Client: Operation returned an invalid status code 'PreconditionFailed'.
Ok so you're seeing the failure in the verbose log but not in the resulting exception. we will take a look, thanks
We are still digging at this one.. That its showing in the Log and NOT in lastexception is what is odd.
The log writer is what is actually populating that property.
Still working at the use case that causes it.
out of curiosity @zsybupt , are you using the client in a Function / Website / API endpoint? and if so are you using .clone or are you reusing the same instance of the client?
Thinking it might be a concurrency issue.
We have also received the same problem with inner exceptions not being surfaced the correct way. From the way we read the code we think that the problem is that this code
https://github.com/microsoft/PowerPlatform-DataverseServiceClient/blob/dfba939dbbfe967c5ef339dfffa70ba41b7196ab/src/GeneralTools/DataverseClient/Client/ServiceClient.cs#L2056-L2062
Uses the ServiceClient._logEntry. The code throwing the exception and storing it is this code: https://github.com/microsoft/PowerPlatform-DataverseServiceClient/blob/dfba939dbbfe967c5ef339dfffa70ba41b7196ab/src/GeneralTools/DataverseClient/Client/ConnectionService.cs#L2217-L2219 but that code logs it to ConnectionService.logEntry resulting in a disconnect between the two logEntries.
From what we can tell there is no sharing of information between ServiceClient._logEntry and ConnectionService.logEntry, meaning that when the code tries to use ServiceClient._logEntry.LastException for exceptions then it will be null, since the exception is stored in ConnectionService.logEntry.
Maybe one way to solve it would be to give ConnectionService the DataverseTraceLogger created in ServiceClient instead of having ConnectionService creating a new one?
edit: formatting
@nicro950 I am very sorry for the long delay in responding here.
The ConnectionService is handed a copy the logger from the service client if it exists, if it does not exist, then the Connection Service will create a local copy based on what it has.
The code that manages the creation of the connection service is here: https://github.com/microsoft/PowerPlatform-DataverseServiceClient/blob/dd3a3893d135bcb8c023e9d700824f2effd28786/src/GeneralTools/DataverseClient/Client/ServiceClient.cs#L1114
Can you test this scenario in the 1.0.23 drop and tell me if you still see this issue?
@MattB-msft It looks like it works now, but if we re-enable the UseWebApi then it starts failing again. Did some more digging, and it might look like it is a cache problem.
Came over this code as part of the CreateServiceConnection:
https://github.com/microsoft/PowerPlatform-DataverseServiceClient/blob/b483aee3feb4cd79095764e7c59131393b62c6d2/src/GeneralTools/DataverseClient/Client/ServiceClient.cs#L1260-L1265
which retrives an ConnectionService from an static in memory cache:
https://github.com/microsoft/PowerPlatform-DataverseServiceClient/blob/b483aee3feb4cd79095764e7c59131393b62c6d2/src/GeneralTools/DataverseClient/Client/ConnectionService.cs#L933-L940
And stores it in 5 minutes
https://github.com/microsoft/PowerPlatform-DataverseServiceClient/blob/b483aee3feb4cd79095764e7c59131393b62c6d2/src/GeneralTools/DataverseClient/Client/ConnectionService.cs#L956-L960
Meaning that the first request works as intended, but subsequent request within 5 minutes would log to the original connection created, instead of the new Connection created as part of the new ServiceClient.
The new created _connectionSvc looks like it is overridden here:
https://github.com/microsoft/PowerPlatform-DataverseServiceClient/blob/b483aee3feb4cd79095764e7c59131393b62c6d2/src/GeneralTools/DataverseClient/Client/ServiceClient.cs#L1268-L1272
With the cached version, resulting in that ServiceClient and ConnectionService has different log instances.
We are creating a new ServiceClient for each request (registered as a scoped service), since i testet with registering it as a singleton in dependency injection but if i remember it correctly then that resulted in different problems down the road. We are using it in conjunction with OrganizationServiceContext (also registered as a scoped service) just to add a little more information.
Working though cleaning up issues. -- and I am very sorry for the delay's in responding. I lost track of this one.
In general, Please do not override the default behavior of UseWebApi unless we tell you otherwise. Prior to .23, the default setting for UseWebAPI was 'true' and for .23 and post it was set to 'False' by default.
This choice was taken due to a large number of translation and caching issues we were getting, where we could not reasonably solve them without incurring additional performance impacts. By disabling UseWebAPI, we increased performance for the system and reduced memory footprint, in addition to resolving several 'special case' issues we had to code for due to the variation between a standard ODATA 4 contract and what is used for Dataverse.
In regard to the specific issue, Null's in exceptions, I think we have locked this down for the most part at this point. if you see this going forward, please do raise it to us.