Overview
When using North52, being able to understand a trace log can help you to resolve any issues you come across during the development and testing of your formulas.
Note: There are multiple sections from different trace logs in this article, we will review each of them individually.
Plugin Context
A formula trace will start with information about the Plugin Context:
~********************* Start PlugIn Context Info ********************* UserId: 0aad6d4c-f237-44b0-9b00-8c0540d166dc OrganizationId: 94584a47-3818-413e-bac1-26cd8a674302 OrganizationName: orgfae6242c MessageName: Update Stage: 40 Mode: 0 PrimaryEntityName: account SecondaryEntityName: none Parent PrimaryEntityName: account Parent MessageName: Update BusinessUnitId: a0dedc30-9a91-ea11-a811-000d3ab6d424 CorrelationId: 1051106e-f92d-467f-9ee0-b08141515a54 Depth: 1 InitiatingUserId: 0aad6d4c-f237-44b0-9b00-8c0540d166dc IsExecutingOffline: False IsInTransaction: True IsolationMode: 2 Mode: 0 OperationCreatedOn: 6/11/2020 1:32:29 PM OperationId: 37cd2b04-c2b0-4f9c-8a70-df285bb222a3 PrimaryEntityId: 60ee4899-0dab-ea11-a812-000d3aba6b7b OwningExtension LogicalName: sdkmessageprocessingstep OwningExtension Name: North52.FormulaManager.Plugins.AnyEntity.SingleFormula: account : Update : PostInsideTransaction OwningExtension Id: f0ee7b47-98a9-ea11-a812-000d3aba6b7b SharedVariables: PrimitiveValue: IsAutoTransact: True;In the above, you can see the following useful information:
- This is a Stage 40 plugin - which means it executed post-operation
- The message name is Update - something changed on an already existing record, i.e. Not a Create or Delete Operation etc.
- It was fired against the Account entity
- It's Depth is 1 - this is the first step in the Execution Pipeline
- The more consecutive layers of logic that are triggered by this action will increase the Depth (Microsoft uses depth count to detect infinite loops)
- In online instances the max Depth allowed is 16
- In on-premise instances the default is 8, but it can be raised by using PowerShell scripts
- The date and time the plugin fired
You can learn more about the execution pipeline here: https://docs.microsoft.com/en-us/powerapps/developer/common-data-service/event-framework#event-execution-pipeline
Changed Attributes (Fields)
InputParameters: Target: ********************* Entity Trace for account ********************* EntityId: a0b69702-0eab-ea11-a812-000d3aba6b7b Attributes:[ PrimitiveValue: name: Name13; PrimitiveValue: accountid: a0b69702-0eab-ea11-a812-000d3aba6b7b; PrimitiveValue: modifiedon: 6/15/2020 1:56:52 PM; EntityReference: modifiedby: 0aad6d4c-f237-44b0-9b00-8c0540d166dc; ; Null parameter value for key modifiedonbehalfby ] PrimitiveValue: Target: Microsoft.Xrm.Sdk.Entity; PrimitiveValue: ConcurrencyBehavior: Default;
In the above server-side trace snippet you can see the input parameters - i.e. What has changed. In the above the values that changed are:
- name > changed to Name13
- modifiedon > date and time of save
- modifiedby > Guid of the User who made the change
Formulas Registered for Trigger Event
~GetFormulas: account Count: 1 : 0 ~Validate Configuration: Oty :: True :: True :: 0 ~ColumnNames: accountid :: 0 ~GetSourceEntityPreValues
These lines show how many formulas are being triggered by this server-side save event.
In this case, only 1 formula is registered to be fired: Oty
In the validate configuration line you can see it is listed with two boolean values. Both of these need to be true for the formula to actually execute. If either is false, then the formula wont be triggered.
The boolean values represent if the formula is active and if the attributes that have changed will trigger it.Below you can see a portion of a trace log on a the Account entity that has many Formulas connected:
********************* End PlugIn Context Info ********************* ~GetFormulas: account Count: 14 : 0 ~Validate Configuration: 2MQ :: True :: True :: 0 ~Validate Configuration: i22 :: True :: False :: 0 ~Validate Configuration: 3M0 :: True :: False :: 0 ~Validate Configuration: XQK :: True :: True :: 0 ~Validate Configuration: OTb :: True :: True :: 0 ~Validate Configuration: lt8 :: True :: True :: 0 ~Validate Configuration: 7Hz :: True :: False :: 0 ~Validate Configuration: YVu :: True :: False :: 0 ~Validate Configuration: XQN :: True :: False :: 0 ~Validate Configuration: qFw :: True :: False :: 0 ~Validate Configuration: oxG :: True :: False :: 0 ~Validate Configuration: g2W :: True :: False :: 0 ~Validate Configuration: bXn :: True :: False :: 0 ~Validate Configuration: BoM :: True :: False :: 0
However only 4 of the 14 formulas are True :: True, so it makes understanding the complex log easier.
Start Single Formula execution
He we will cover what actually happens during function execution.
We will use the following formula for our example:
This formula is creating an auto number. The specific requirement is that the first 3 characters of the account name is used as a prefix and that when generating the AutoNumber we need to count the number of existing prefix records and increment by one. You can see the detailed example here: https://support.north52.com/knowledgebase/article/KA-01066-dynamics-crm-365-xRM-Formula-062-Advanced-AutoNumber/en-us
Formula Execution
We will analyse this Formula and determine what function will execute first, and how the output of a function becomes the input for another function.
The account name here is Microsoft - UK.
The first statement to execute will be the Left([account.name], 3)
North52 functions will execute left to right and inside out. In this example the Upper(Left([account.name], 3)) doesn't depend on anything else executing first, but the Upper() function needs the output of the Left([account.name], 3) function before it can execute.
In the trace log you will see
Function Name: left Value: Mic (the output of the Left() function is Mic and this becomes the input for the Upper() function)Function Name: upper Value: MIC (the output of the Upper() function is MIC)
The next function to execute will be populating the SetParams() of the FindCountFD().
Again it's an Upper(Left([account.name], 3)), so you will see a repeat of the first two function outputs in the trace log:
Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: left Value: Mic
Function Name: upper Value: MIC
Next the SetParams() value will be populated with the output of the Upper() being added to a % symbol:
SetParams( Upper(Left([account.name] ,3)) + '%' )Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: setparams Value: MIC%
Next comes the evaluation of the FindCountFD() function. In the trace log you will be able to see the Fetch-XML that was executed:
Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: setparams Value: MIC%
FetchXml-A.: <fetch distinct='false' mapping='logical' no-lock='true' aggregate='true'>
<entity name="account">
<attribute name='accountnumber' alias='accountnumber_count' aggregate='count' /> <filter type="and"> <condition attribute="accountnumber" operator="like" value="MIC%" /> </filter> </entity> </fetch>
Function Name: findcountfd Value: 3
The FindCountFD() function returns a value a 3.
FindCountFD('GetCurrentAutoValue','accountnumber','0',true,SetParams( Upper(Left([account.name] ,3)) + '%' ))+1
The result of the FindCountFD() is incremented by 1 giving a value of 4.
That number is then the input of the PadLeft() function:
PadLeft(FindCountFD('GetCurrentAutoValue','accountnumber','0',true,SetParams( Upper(Left([account.name] ,3)) + '%' )) +1,4,'0')
PadLeft( 4,4,'0') is what is actually executed: Pad to the left of the value 4, with zeros until we have a 4 digit string:Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: setparams Value: MIC%
FetchXml-A.:
<fetch distinct='false' mapping='logical' no-lock='true' aggregate='true'>
<entity name="account">
<attribute name='accountnumber' alias='accountnumber_count' aggregate='count' />
<filter type="and">
<condition attribute="accountnumber" operator="like" value="MIC%" />
</filter>
</entity>
</fetch>
Function Name: findcountfd Value: 3
Function Name: padleft Value: 0004
So now we have evaluated all function calls: 'MIC' + '-' + '0004'
Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: left Value: Mic
Function Name: upper Value: MIC
Function Name: setparams Value: MIC%
FetchXml-A.:
<fetch distinct='false' mapping='logical' no-lock='true' aggregate='true'>
<entity name="account">
<attribute name='accountnumber' alias='accountnumber_count' aggregate='count' />
<filter type="and">
<condition attribute="accountnumber" operator="like" value="MIC%" />
</filter>
</entity>
</fetch>
Function Name: findcountfd Value: 3
Function Name: padleft Value: 0004Function Name: padleft Value: 0004
~Result: MIC-0004
This value is then put into the Account Number field:
Entity Trace for north52_formula
The entity trace for the North52 formula appears next and will give you plenty of relevant information about the settings on formula that was triggered.
~********************* Entity Trace for north52_formula *********************
EntityId: 6d9503b9-bbab-ea11-a812-000d3aba6b7b
Attributes:[
PrimitiveValue: north52_checksum: 16D5887A6BE54E96E8E2C12902EC3061;
OptionSetValue: north52_executeas: 217890000;
OptionSetValue: north52_executionprocess: 217890000;
OptionSetValue: north52_pipelineevent: 217890002;
PrimitiveValue: north52_formuladescription: UpdateRecord('account', [account.accountid], SetAttribute('fax', '0211234567') ) ;
OptionSetValue: north52_pipelinestage: 217890001;
PrimitiveValue: north52_deploymentsolution: North52FormulaManagerDeploymentSolution;
PrimitiveValue: north52_version: 9dec3b94-c248-4d30-8096-4effe2cb8ac4;
OptionSetValue: north52_tracinglevel: 217890001;
PrimitiveValue: north52_enablefindfunctionfetchxmloptimization: True;
PrimitiveValue: north52_enableprevaluecheck: False;
OptionSetValue: north52_mode: 217890002;
OptionSetValue: north52_displayformat: 217890000;
PrimitiveValue: createdon: 6/11/2020 8:15:34 AM;
OptionSetValue: north52_formulatype: 217890013;
PrimitiveValue: north52_sourceentityproperty: name|address1_line1|address1_line2|address1_line3;
PrimitiveValue: north52_sourceentityname: account;
PrimitiveValue: north52_shortcode: Oty;
PrimitiveValue: north52_name: Account - Save - Perform Action - Thu Jun 11 2020 09:15:34 GMT+0100 (British Summer Time);
PrimitiveValue: north52_formulaid: 6d9503b9-bbab-ea11-a812-000d3aba6b7b;
FormattedValue: north52_executeas: Calling User;
FormattedValue: north52_executionprocess: Dynamics Sandbox;
FormattedValue: north52_pipelineevent: Create & Update;
FormattedValue: north52_pipelinestage: Post-Operation (Synchronous);
FormattedValue: north52_tracinglevel: Information;
FormattedValue: north52_enablefindfunctionfetchxmloptimization: Yes;
FormattedValue: north52_enableprevaluecheck: No;
FormattedValue: north52_mode: Server Side;
FormattedValue: north52_displayformat: String;
FormattedValue: createdon: 11/06/2020 08:15;
FormattedValue: north52_formulatype: Save - Perform Action;
]
Relevant pieces of information:
- north52_sourceentityname - what entity the Formula is executing against
- north52_sourceentitypropertyname what are the triggers for the Formula
- north52_pipelinestage - where the event execution pipeline is the Formula going to fire
- north52_formulatype - e.g. Formula type: Save - Perform Action, Save - To Current Record, Process Genie, etc.