Troubleshooting Dynamics CRM: The Mother of all call stacks

So one of my customers ran into this issue while opening an Opportunity.  As you can see, a custom plugin was throwing an exception because it could not find a Account with a specified ID.

SNAGHTML5c035ae

That part is 100% correct.  The Account with that ID indeed does not exist in the database.

The problem is, this plugin should never have been fired. As I mentioned, this was happening on a Retrieve operation and there are no plugins registered against the Retrieve Message.

So I waited until tonight so I could turn on Tracing (on-premise, of course), and this is what I found:

[2014-10-16 20:12:57.600] Process: w3wp |Organization:d98bbf24-8eed-4cb4-a379-6aa848499cb0 |
    Thread:   25 |Category: Exception |User: fb9a439c-b578-4a4b-83e0-39ea0059ad2a |
    Level: Error |ReqId: eb0bc9e4-e6e6-4552-b322-1c2fa0bdbc10 | 
    CrmException..ctor  ilOffset = 0x7

    at CrmException..ctor(String message, Exception innerException, Int32 errorCode,
       Boolean isFlowControlException)  ilOffset = 0x7

    at CrmException..ctor(String message, Exception innerException, Int32 errorCode)  ilOffset = 0x5
    at RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig,
       Boolean constructor)  ilOffset = 0xFFFFFFFF

    at RuntimeConstructorInfo.Invoke(BindingFlags invokeAttr, Binder binder,
       Object[] parameters, CultureInfo culture)  ilOffset = 0xF7

    at RuntimeType.CreateInstanceImpl(BindingFlags bindingAttr, Binder binder, Object[] args,
       CultureInfo culture, Object[] activationAttributes, StackCrawlMark& stackMark)  ilOffset = 0x1E8

    at Activator.CreateInstance(Type type, BindingFlags bindingAttr, Binder binder, Object[] args,
       CultureInfo culture, Object[] activationAttributes)  ilOffset = 0xBB

    at Activator.CreateInstance(Type type, Object[] args)  ilOffset = 0xA
    at VersionedPluginProxyStepBase.WrapExceptionToThrow(CrmException exception)  ilOffset = 0xD3
    at VersionedPluginProxyStepBase.Execute(PipelineExecutionContext context)  ilOffset = 0x65
    at Pipeline.Execute(PipelineExecutionContext context)  ilOffset = 0x65
    at MessageProcessor.Execute(PipelineExecutionContext context)  ilOffset = 0x1C5
    at InternalMessageDispatcher.Execute(PipelineExecutionContext context)  ilOffset = 0xE4
    at ExternalMessageDispatcher.ExecuteInternal(IInProcessOrganizationServiceFactory serviceFactory,
       IPlatformMessageDispatcherFactory dispatcherFactory, String messageName, String requestName, 
       Int32 primaryObjectTypeCode, Int32 secondaryObjectTypeCode, ParameterCollection fields, 
       CorrelationToken correlationToken, CallerOriginToken originToken, UserAuth userAuth, Guid callerId,
       Guid transactionContextId, Int32 invocationSource, Nullable`1 requestId, Version endpointVersion)  ilOffset = 0x156

    at OrganizationSdkServiceInternal.ExecuteRequest(OrganizationRequest request, CorrelationToken correlationToken,
       CallerOriginToken callerOriginToken, WebServiceType serviceType, UserAuth userAuth, Guid targetUserId, 
       Boolean traceRequest, OrganizationContext context, Boolean returnResponse)  ilOffset = 0x145

    at OrganizationSdkServiceInternal.ExecuteRequest(OrganizationRequest request, CorrelationToken correlationToken,
       CallerOriginToken callerOriginToken, WebServiceType serviceType)  ilOffset = 0x3D

    at OrganizationSdkServiceInternal.Retrieve(String entityName, Guid id, ColumnSet columnSet,
       CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType)  ilOffset = 0x66

    at InprocessServiceProxy.RetrieveCore(String entityName, Guid id, ColumnSet columnSet)  ilOffset = 0x28
    at OrganizationServiceProxy.Retrieve(String entityName, Guid id, ColumnSet columnSet)  ilOffset = 0x4
    at Utility.UpdateAccountKeyword(IOrganizationService service, Guid accountId)  ilOffset = 0xE8 
        C:\Plugins\SupportingClasses\Utility.cs(205)

    at InvoiceCancelOpportunityCloseKeywords.Execute(IServiceProvider serviceProvider)  ilOffset = 0x164 
        C:\Plugins\InvoiceCancelOpportunityCloseKeywords.cs(70)

    at V5PluginProxyStep.ExecuteInternal(PipelineExecutionContext context)  ilOffset = 0xD0
    at VersionedPluginProxyStepBase.Execute(PipelineExecutionContext context)  ilOffset = 0x65
    at Pipeline.Execute(PipelineExecutionContext context)  ilOffset = 0x65
    at MessageProcessor.Execute(PipelineExecutionContext context)  ilOffset = 0x1FB
    at InternalMessageDispatcher.Execute(PipelineExecutionContext context)  ilOffset = 0xE4
    at ExtensiblePlatformMessageDispatcher.Execute(PipelineExecutionContext pluginContext)  ilOffset = 0x0
    at ExtensiblePlatformMessageDispatcher.UpdateWithInvocationSource(BusinessEntity entity, FilterExpression filter,
       Int32 invocationSource, ExecutionContext context)  ilOffset = 0xCE

    at ExtensiblePlatformMessageDispatcher.Update(BusinessEntity entity, FilterExpression filter, ExecutionContext context) 
       ilOffset = 0x5

    at BusinessProcessObject.UpdateWithPipelineAndExtensions(IBusinessEntity entity, ExecutionContext context)  ilOffset = 0x78
    at QOIPriceService.UpdateEntity(BusinessEntity newQoi, BusinessEntity oldQoi, ExecutionContext context)  ilOffset = 0x87
    at PriceService.CalculatePrice(BusinessEntity entity, Guid lineItemId, Boolean skipQOIDetailPricing,
       Boolean overridePricePerUnitLock, Boolean overrideDiscountLock, ExecutionContext context)  ilOffset = 0x6E1

    at OpportunityPriceService.CalculatePrice(BusinessEntity entity, Guid lineItemId, Boolean skipQOIDetailPricing,
       Boolean overridePricePerUnitLock, Boolean overrideDiscountLock, ExecutionContext context)  ilOffset = 0x70

    at QOIPriceService.CalculatePrice(Guid qoiId, Guid lineItemId, Boolean skipLineItemPricing, Boolean overridePricePerUnitLock,
       Boolean overrideDiscountLock, Boolean isModifiedBySystem, ExecutionContext context)  ilOffset = 0x2E

    at OpportunityService.CalculatePrice(Guid opportunityId, Guid opportunityProductId, Boolean skipOpportunityProductPricing,
       Boolean overridePricePerUnitLock, Boolean overrideDiscountLock, Boolean isModifiedBySystem, ExecutionContext context) 
       ilOffset = 0x12

    at QOIService.Retrieve(BusinessEntityMoniker moniker, EntityExpression entityExpression, ExecutionContext context,
       Boolean isModifiedBySystem, Boolean calculatePrice, Int32 state)  ilOffset = 0x2D

    at OpportunityService.Retrieve(BusinessEntityMoniker moniker, EntityExpression entityExpression,
       ExecutionContext context)  ilOffset = 0x14

    at RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig,
       Boolean constructor)  ilOffset = 0xFFFFFFFF

    at RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments) 
       ilOffset = 0x25

    at RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder,
       Object[] parameters, CultureInfo culture)  ilOffset = 0x89

    at LogicalMethodInfo.Invoke(Object target, Object[] values)  ilOffset = 0x4F
    at InternalOperationPlugin.Execute(IServiceProvider serviceProvider)  ilOffset = 0x57
    at V5PluginProxyStep.ExecuteInternal(PipelineExecutionContext context)  ilOffset = 0x58
    at VersionedPluginProxyStepBase.Execute(PipelineExecutionContext context)  ilOffset = 0x65
    at Pipeline.Execute(PipelineExecutionContext context)  ilOffset = 0x65
    at MessageProcessor.Execute(PipelineExecutionContext context)  ilOffset = 0x1C5
    at InternalMessageDispatcher.Execute(PipelineExecutionContext context)  ilOffset = 0xE4
    at ExternalMessageDispatcher.ExecuteInternal(IInProcessOrganizationServiceFactory serviceFactory,
        IPlatformMessageDispatcherFactory dispatcherFactory, String messageName, String requestName, 
        Int32 primaryObjectTypeCode, Int32 secondaryObjectTypeCode, ParameterCollection fields, 
        CorrelationToken correlationToken, CallerOriginToken originToken, UserAuth userAuth, Guid callerId, 
        Guid transactionContextId, Int32 invocationSource, Nullable`1 requestId, Version endpointVersion)  ilOffset = 0x156

    at OrganizationSdkServiceInternal.ExecuteRequest(OrganizationRequest request, CorrelationToken correlationToken,
        CallerOriginToken callerOriginToken, WebServiceType serviceType, UserAuth userAuth, Guid targetUserId, 
        Boolean traceRequest, OrganizationContext context, Boolean returnResponse)  ilOffset = 0x145

    at OrganizationSdkServiceInternal.ExecuteRequest(OrganizationRequest request, CorrelationToken correlationToken,
       CallerOriginToken callerOriginToken, WebServiceType serviceType)  ilOffset = 0x3D

    at OrganizationSdkServiceInternal.Execute(OrganizationRequest request, CorrelationToken correlationToken,
       CallerOriginToken callerOriginToken, WebServiceType serviceType)  ilOffset = 0x24

    at InprocessServiceProxy.ExecuteCore(OrganizationRequest request)  ilOffset = 0x34
    at PlatformCommand.XrmExecuteInternal()  ilOffset = 0xF6
    at RetrieveCommand.Execute()  ilOffset = 0x2
    at EntityProxy.Retrieve(String[] columns, Guid auditingTransactionId, Boolean addRequiredColumns)  ilOffset = 0x69
    at EntityProxy.Retrieve(String[] columns, Guid auditingTransactionId)  ilOffset = 0x4
    at EntityProxy.Retrieve(String columnSet, Guid auditingTransactionId)  ilOffset = 0xB
    at EntityProxy.Retrieve(String columnSet)  ilOffset = 0x7
    at AppForm.FormLoadEvent()  ilOffset = 0x11
    at AppForm.RaiseDataEvent(FormEventId eventId)  ilOffset = 0xC7
    at EndUserForm.Initialize(Entity entity)  ilOffset = 0x1F
    at CustomizableForm.Execute(Entity entity, FormDescriptor fd)  ilOffset = 0x62
    at RecordPageHandler.ConfigureFormWrapper()  ilOffset = 0xC
    at GenericEventProcessor.RaiseEvent(String eventName)  ilOffset = 0x2D
    at PageManager.OnPreRender(EventArgs e)  ilOffset = 0x47
    at Control.PreRenderRecursiveInternal()  ilOffset = 0x54
    at Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)  ilOffset = 0x6D3
    at Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)  ilOffset = 0x3C
    at Page.ProcessRequest()  ilOffset = 0x14
    at Page.ProcessRequest(HttpContext context)  ilOffset = 0x33
    at CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()  ilOffset = 0x18D
    at HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)  ilOffset = 0x15
    at ApplicationStepManager.ResumeSteps(Exception error)  ilOffset = 0x10A
    at HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(HttpContext context, AsyncCallback cb, Object extraData)  ilOffset = 0x5C
    at HttpRuntime.ProcessRequestInternal(HttpWorkerRequest wr)  ilOffset = 0x16A
    at ISAPIRuntime.ProcessRequest(IntPtr ecb, Int32 iWRType)  ilOffset = 0x4B

That is 75 calls, if you didn’t feel like counting, and in the middle of all of that was the failing call to my plugin.

The nearest thing I can figure is that this Opportunity is set to be System Calculated and when it was opened, a update to the revenue numbers. This ended up firing my plugin which failed because data that was passed to it turned out to be invalid.

I temporarily disabled the plugin and was able to save the Opportunity and correct the invalid data issue.

I could not have done this troubleshooting without the following tools:

If you do not have these tools in your toolbox, you need to fix that today.

Leave a Reply 2 comments