Views:

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.
 

Decision Table - Start Single Formula execution

In a Decision Table:
  • each sheet executes left to right in order
  • each row in each sheet executes left to right
  • the rows execute top to bottom in order
This means that the Decision Sheet on the left will execute first - Validation
In the below example the Decision Sheets will execute in this order:
  • Validation
  • Taxable Salary
  • Determine Max Rate
  • Standard Rate Tax
  • Higher Rate Tax
  • Combined Tax
  • Tax Credit Deductions
  • Update Record


We can see this reflected in the tracelog:


  
~********************* Start Formula Execution: 6cV *********************
This indicates that the formula is starting
  
Decision Table Start: (validation) 

-Row:4 
Function: doesnotcontaindata Value: False
Function: doesnotcontaindata Value: False
Function: iftrue Value: NoOp

Decision Table End: (validation) FEM:377 Value: NoOp

In the trace log, each Decision Sheet is clearly identified - so you can see where the Sheet begins executing, the results of each Row that executes, and where it ends.
In the above example, we can see that on the Validation sheet, the DoesNotContainData() function was executed twice on Row 4, and both times returned False
  
Decision Table Start: (higher rate tax) 

-Row:4 
Function: getvar-taxablesalary Value: 83000.0000000000
Function: getvar-cutoff Value: 42000
Function: getvar-taxablesalary Value: 83000.0000000000
Function: getvar-cutoff Value: 42000
Function: setvar-higher rate taxable amount Value: 41000.0000000000
Function: getvar-higher rate taxable amount Value: 41000.0000000000
Function: setvar-higher rate tax due Value: 16400.00000000000
Function: iftrue Value: 16400.00000000000

Decision Table End: (higher rate tax) FEM:1 Value: 16400.00000000000

On the Higher Tax Rate sheet, on Row 4 a value for higher rate taxable amount was set to 41000, and higher rate tax due was set at 16400

  
Decision Table Start: (update record) 

-Row:4 
Function: getvar-tax payment due Value: 22300.00000000000
Function: setattribute Value: n52tax_netsalary|77700.00000000000
Function: getvar-tax payment due Value: 22300.00000000000
Function: setattribute Value: n52tax_totaltaxpayment|22300.00000000000
Function: updaterecord EntityName: contact Value: 76c5a5d8-28ac-ec11-983f-002248836b52
Function: iftrue Value: 76c5a5d8-28ac-ec11-983f-002248836b52

Decision Table End: (update record) FEM:2948 Value: 76c5a5d8-28ac-ec11-983f-002248836b52

On the sheet called Update Record, we can see the n52tax_netsalary attribute was set to 77700 and the n52tax_totaltaxpayment was set to 22300.
We can also see that the UpdateRecord() function updated a Contact record with a Guid of 76c5a5d8-28ac-ec11-983f-002248836b52 using the attributes set on the lines above.

 

Classic - Start Single Formula execution

Here we will cover what actually happens during classic 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: 0004
Function 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.