Looking for PowerObjects? Don’t worry, you’re in the right place! We’ve been part of HCL for several years, and we’ve now taken the final step in our acquisition journey: moving our website to the HCL domain. Nothing else is changing – we are still fanatically focused on Microsoft Business Applications!

PowerObjects Blog 

for Microsoft Business Applications


Debugging Your Plug-ins with the Plug-in Trace Log

Post Author: Joe D365 | July 5th, 2016

Dynamics CRM developers can sometimes find it difficult to debug plug-ins for CRM Online since they don't have the luxury to debug them the same way they do it while writing plug-ins for CRM On-premises. Luckily, a new feature called Plug-in Trace Log was included with Dynamics CRM 2016, and in today's blog, we'll be showing you how you can debug your plug-ins using this new feature.

The Plug-in Trace Log feature saves trace log information, similar to the information you get when an asynchronous plug-in throws an exception, with the advantage that trace log information will be available even when the plug-in doesn't throw an exception. The steps needed to use this feature are broken down below.

1. Write the Plug-in

First, let's write a simple plug-in to test the new Plug-in Trace Log feature. Notice that in the sample code below, we added an instance of ITracingService to log information about the execution of the plug-in as well as logging some key values:

Plug-in Trace Log

2. Register the Plug-in

For this exercise, we will register this plug-in as follows:

Plug-in Trace Log

3. Enable Plug-in Trace Log

To enable the Plug-in Trace Log, first navigate to Mail > Settings > Administration.

Plug-in Trace Log

Once you're in the Administration section, click on System Settings.

Plug-in Trace Log

From here you can navigate to the Customization tab and select All for the Enable logging to plug-in trace log field. Then click OK.

Plug-in Trace Log

Test the Plug-in Trace Log

To test the Plug-in Trace Log, open any Account record, update the Fax Number and click on Save.

To check the Plug-in Trace Log entries, click on Main > Settings > Plug-in Trace Log.

Plug-in Trace Log

Double click on the entry created right after you updated the Account record. Keep in mind that the Trace Log record is created asynchronously, it might take a few seconds for the entry to show in the view.

Plug-in Trace Log

Once the Trace Log record opens you can investigate the information captured. This page will provides valuable information such as Type Name, Message Type, Primary Entity, Depth, Mode, etc.

Plug-in Trace Log

Scroll down and check the Message Block under the Execution tab. This is where you will find the trace log information you configured in your plug-in.

Plug-in Trace Log

IMPORTANT: only enable the Plug-in Trace Log feature if you are debugging or tweaking a plug-in. You don't want to create thousands of trace log records if you are not debugging a plug-in.

That's all for the blog today! You can learn more about the features included in Dynamics CRM 2016 by subscribing to our blog as well as viewing our numerous Webinars on Demand. The CRM Book has been updated to include content for Dynamics CRM 2016 as well, so make sure you check it out!

Happy CRM'ing!

Joe CRM
By Joe D365
Joe D365 is a Microsoft Dynamics 365 superhero who runs on pure Dynamics adrenaline. As the face of PowerObjects, Joe D365’s mission is to reveal innovative ways to use Dynamics 365 and bring the application to more businesses and organizations around the world.

10 comments on “Debugging Your Plug-ins with the Plug-in Trace Log”

  1. Getting the error while uninstalling Managed solution containing custom activity getting error "'Attribute' metadata entity doesn't contain metadata attribute with Name = 'schema name'"
    After I go through the trace logs, I found that the solution is searching for attribute of custom activity entity from Attribute View in database and the attribute name is 'subject' . After It performs below operation, system throws above error:
    at CrmDbConnection.InternalExecuteReader(IDbCommand command, Boolean capturePerfTrace) ilOffset = 0x181 at CrmDbConnection.ExecuteReader(IDbCommand command, Boolean impersonate, Boolean capturePerfTrace) ilOffset = 0x24 at DBCommandExecutor.ExecuteQuery(IDbCommand command, ISqlExecutionContext context) ilOffset = 0x45 at MetadataQueryLibrary.RetrieveMultiple(SimpleQueryExpression queryExpression, ISqlExecutionContext context, DatabaseQueryTarget queryTarget) ilOffset = 0x2D at MetadataEntityFacadeBridge.RetrieveEntity(Guid id, ExecutionContext context) ilOffset = 0x58 at EntityFacadeBridgeBase.FillEntityColumns(IEntity entity, ExecutionContext context) ilOffset = 0x8 at ComponentStateTransition.LookupEntityNameAndIdForErrorMessage(IEntity entity, ExecutionContext context, String& entityName, Guid& entityId, String& nameAttributeValue) ilOffset = 0x34 at ComponentStateTransition.LookupEntityNameAndIdForErrorMessage(BusinessComponentState state, ISqlExecutionContext context, String& entityName, Guid& entityId, String& nameAttributeValue) ilOffset = 0x38 at ComponentStateTransition.DeleteAllComponentRows(BusinessComponentState currentState, ISqlExecutionContext context, Boolean skipValidation) ilOffset = 0x85 at UninstallDeleteProtectedTransition.ConstructActionSet(Int32 componentType, Guid objectId, Object operationParameter, BusinessComponentState currentState, ISqlExecutionContext context) ilOffset = 0x18D at ComponentStateTransition.Execute(Int32 componentType, Guid objectId, Object operationParameter, BusinessComponentState currentState, ISqlExecutionContext context) ilOffset = 0xD at MetadataProcessObject.DoDelete(MetadataBusinessEntityMoniker moniker, ISqlExecutionContext context) ilOffset = 0x6C at MetadataProcessObject.Delete(MetadataBusinessEntityMoniker moniker, ISqlExecutionContext sqlContext) ilOffset = 0x24 at AttributeDeleteAction.DeleteAttributeAndRelated(Guid attributeId, AttributeTypeInfo attributeType, Nullable1 optionSetId, MetadataHelper helper) ilOffset = 0x57 at EntityDeleteAction.DeleteEntityAttributes(MetadataProcessObject mpo) ilOffset = 0x1FE at EntityDeleteAction.MetabaseOperation() ilOffset = 0x70 at MetadataHelper.ProcessQueue_metabaseActionsToExecute(CounterList listCounters) ilOffset = 0x123 at MetadataHelper.ProcessQueue() ilOffset = 0x73 at EntityService.Delete(Guid entityId, MetadataHelper metadataHelper, Boolean suppressSecurityCacheFlush, ExecutionContext context) ilOffset = 0x1FC at EntityUninstallHandler.DeleteComponent(ComponentTypeMapData componentTypeData, Guid componentObjectId, SolutionUninstallContext solutionUninstallContext) ilOffset = 0x0 at SolutionComponentUninstaller.Uninstall(ComponentTypeMapData componentTypeData, Guid componentObjectId, SolutionUninstallContext solutionUninstallContext) ilOffset = 0x76 at TypeUninstallHandler.UninstallComponent(SolutionComponentUninstaller uninstaller, BusinessEntity entity, SolutionUninstallContext solutionUninstallContext) ilOffset = 0x0 at TypeUninstallHandler.Uninstall(SolutionUninstallContext solutionUninstallContext) ilOffset = 0xB1 at SolutionUninstallService.UninstallComponentTypeFromSolution(Int32 componentType, SolutionUninstallContext solutionUninstallContext) ilOffset = 0x1D at SolutionUninstallService.Uninstall(ISolution solution, DynamicMetadataCache cache, ExecutionContext context) ilOffset = 0x149 at SolutionServiceInternal1.DeleteInternal(List1 solutions, ExecutionContext context) ilOffset = 0x97 at SolutionServiceInternal1.Delete(BusinessEntityMoniker moniker, ExecutionContext context) ilOffset = 0x49 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 = 0xCF at LogicalMethodInfo.Invoke(Object target, Object[] values) ilOffset = 0x4F at InternalOperationPlugin.Execute(IServiceProvider serviceProvider) ilOffset = 0x57 at V5PluginProxyStep.ExecuteInternal(PipelineExecutionContext context) ilOffset = 0x265 at VersionedPluginProxyStepBase.Execute(PipelineExecutionContext context) ilOffset = 0x65 at PipelineInstrumentationHelper.Execute(Boolean instrumentationEnabled, String stopwatchName, ExecuteWithInstrumentation action) ilOffset = 0x2D at Pipeline.Execute(PipelineExecutionContext context) ilOffset = 0xD8 at c__DisplayClass1.b__0() ilOffset = 0x0 at PipelineInstrumentationHelper.Execute(Boolean instrumentationEnabled, String stopwatchName, ExecuteWithInstrumentation action) ilOffset = 0x2D at MessageProcessor.RunStage(PipelineExecutionContext context, Int32 pipelineStage) ilOffset = 0x39 at MessageProcessor.Execute(PipelineExecutionContext context) ilOffset = 0x1E6 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 callerRegardingObjectId, UserType userType, Guid transactionContextId, Int32 invocationSource, Nullable`1 requestId, Version endpointVersion) ilOffset = 0x1F2 at OrganizationSdkServiceInternal.ExecuteRequestRequestWithInstrumentation(OrganizationRequest request, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, UserAuth userAuth, Guid targetUserId, OrganizationContext context, Boolean returnResponse, Boolean checkAdminMode, Object operation, UserType targetUserType) ilOffset = 0x28B at OrganizationSdkServiceInternal.ExecuteRequest(OrganizationRequest request, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, UserAuth userAuth, Guid targetUserId, Guid targetCallerRegardingObjectId, UserType targetUserType, OrganizationContext context, Boolean returnResponse, Boolean checkAdminMode) ilOffset = 0x37 at OrganizationSdkServiceInternal.ExecuteRequest(OrganizationRequest request, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, Boolean checkAdminMode, ExecutionContext executionContext) ilOffset = 0x58 at OrganizationSdkServiceInternal.Delete(EntityReference entityReference, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, Boolean checkAdminMode, Boolean checkOptimisticConcurrency) ilOffset = 0x64 at OrganizationSdkServiceInternal.Delete(String entityName, Guid id, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, Boolean checkAdminMode, Boolean checkOptimisticConcurrency) ilOffset = 0x16 at OrganizationSdkService.Delete(String entityName, Guid id) ilOffset = 0xF at ilOffset = 0xFFFFFFFF at SyncMethodInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs) ilOffset = 0x241 at DispatchOperationRuntime.InvokeBegin(MessageRpc& rpc) ilOffset = 0x100 at ImmutableDispatchRuntime.ProcessMessage5(MessageRpc& rpc) ilOffset = 0x48 at MessageRpc.Process(Boolean isOperationContextSet) ilOffset = 0x62 at Wrapper.Resume(Boolean& alreadyResumedNoLock) ilOffset = 0x1B at ThreadBehavior.SynchronizationContextStartCallback(Object state) ilOffset = 0x0 at ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) ilOffset = 0x70 at ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) ilOffset = 0x4 at QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem() ilOffset = 0x0 at ThreadPoolWorkQueue.Dispatch() ilOffset = 0xA3 Query execution time: 0.0 seconds; database: SystemTest_MSCRM; Server:DWD-IZZ-G-SQL02CRMORGDB; command: SELECT [AttributeId] AS [attributeid], [AttributeRowId] AS [attributerowid], [SolutionId] AS [solutionid], [OverwriteTime] AS [overwritetime], [SupportingSolutionId] AS [supportingsolutionid], [AttributeTypeId] AS [attributetypeid], [Name] AS [name], [PhysicalName] AS [physicalname], [TableColumnName] AS [tablecolumnname], [Length] AS [length], [IsNullable] AS [isnullable], [XmlAbbreviation] AS [xmlabbreviation], [EntityId] AS [entityid], [DefaultValue] AS [defaultvalue], [UpgradeDefaultValue] AS [upgradedefaultvalue], [ColumnNumber] AS [columnnumber], [ValidForUpdateAPI] AS [validforupdateapi], [LogicalName] AS [logicalname], [ValidForReadAPI] AS [validforreadapi], [ValidForCreateAPI] AS [validforcreateapi], [VisibleToPlatform] AS [visibletoplatform], [IsPKAttribute] AS [ispkattribute], [IsCustomField] AS [iscustomfield], [IsLogical] AS [islogical], [DisplayMask] AS [displaymask], [AttributeOf] AS [attributeof], [ValuesFromRelationshipAttribute] AS [valuesfromrelationshipattribute], [ReferencedEntityObjectTypeCode] AS [referencedentityobjecttypecode], [AggregateOf] AS [aggregateof], [IsSortAttribute] AS [issortattribute], [PrecisionValue] AS [precisionvalue], [PrecisionSource] AS [precisionsource], [IsIdentity] AS [isidentity], [IsReplicated] AS [isreplicated], [YomiOf] AS [yomiof], [HasMultipleLabels] AS [hasmultiplelabels], [IsRowGuidAttribute] AS [isrowguidattribute], [IsBaseCurrency] AS [isbasecurrency], [CalculationOf] AS [calculationof], [IsAuditEnabled] AS [isauditenabled], [OptionSetId] AS [optionsetid], [LinkedAttributeId] AS [linkedattributeid], [InheritsFrom] AS [inheritsfrom], [IsStoredOnPrimaryTable] AS [isstoredonprimarytable], [IsInheritanceTypeAttribute] AS [isinheritancetypeattribute], [IsUnmanagedAttribute] AS [isunmanagedattribute], [IsOneWayBooleanAttribute] AS [isonewaybooleanattribute], [CanBeSecuredForCreate] AS [canbesecuredforcreate], [CanBeSecuredForRead] AS [canbesecuredforread], [CanBeSecuredForUpdate] AS [canbesecuredforupdate], [IsSecured] AS [issecured], [ManagedPropertyLogicalName] AS [managedpropertylogicalname], [ManagedPropertyParentComponentType] AS [managedpropertyparentcomponenttype], [ManagedPropertyParentAttributeName] AS [managedpropertyparentattributename], [IsManaged] AS [ismanaged], [AppDefaultValue] AS [appdefaultvalue], [AttributeLogicalTypeId] AS [attributelogicaltypeid], [Locked] AS [locked], [AttributeImeModeId] AS [attributeimemodeid], [AttributeRequiredLevelId] AS [attributerequiredlevelid], [MaxLength] AS [maxlength], [MinValue] AS [minvalue], [MaxValue] AS [maxvalue], [Accuracy] AS [accuracy], [AccuracySource] AS [accuracysource], [LookupStyle] AS [lookupstyle], [LookupBrowse] AS [lookupbrowse], [ImeMode] AS [imemode], [DeprecatedVersion] AS [deprecatedversion], [IsCustomizable] AS [iscustomizable], [IsRenameable] AS [isrenameable], [CanModifySearchSettings] AS [canmodifysearchsettings], [CanModifyRequirementLevelSettings] AS [canmodifyrequirementlevelsettings], [CanModifyAdditionalSettings] AS [canmodifyadditionalsettings], [CanModifyAuditSettings] AS [canmodifyauditsettings], [IntroducedVersion] AS [introducedversion], [IsEncrypted] AS [isencrypted], [SourceType] AS [sourcetype], [FormulaDefinition] AS [formuladefinition], [SourceTypeMask] AS [sourcetypemask], [Behavior] AS [behavior], [CanModifyBehavior] AS [canmodifybehavior], [IsGlobalFilterEnabled] AS [isglobalfilterenabled], [IsSortableEnabled] AS [issortableenabled], [IsSearchable] AS [issearchable], [IsFilterable] AS [isfilterable], [IsRetrievable] AS [isretrievable], [IsFilterableSetBySystem] AS [isfilterablesetbysystem], [IsRetrievableSetBySystem] AS [isretrievablesetbysystem], [CanModifyGlobalFilterSettings] AS [canmodifyglobalfiltersettings], [CanModifyIsSortableSettings] AS [canmodifyissortablesettings] FROM [AttributeAsIfPublishedLogicalView] WHERE (AttributeId = 'Some Guid') ORDER BY [ComponentState] desc; CommandTimeout: 30.

    1. Hi - Yeah - this appears to be fixed in size and we can't increase it. let me see if i can dig up what that maxium is. It is decent size so you only run into it if you have a bunch of logging.

    1. Most likely you don't have plugin trace logs enabled. See the "Customizations" tab in System Settings screen shot above.

  4. Hi there,

    Do you have any sense of the performance hit that you'd experience from adding this kind of tracing into your plugins?

    I'm in the middle of a greenfield implementation of CRM 2016 and we've been adding it extensively to all our custom code as it's a great tool for tracing errors and issues. Someone raised the question yesterday about are there is particular performance considerations that we should be thinking about when we use this functionality as we've been using it to record every method call in the code much like in your example.

    Could we use it so much that it tanks system performance?

    1. The traces are written asynchronously, so the impact "should be minimal". And if you activate the logging (the system setting) only for focused troubleshooting, it should not impact at all when it is generally switched off.
      Also, I would recommend using the Plugin Trace Viewer in XrmToolBox to analyze the logs instead of using the Dynamics UI, which is quite limiting.

      1. The Plugin Trace Viewer is an excellent tool for reading complex trace logs. Thanks @jonasrapp:disqus for all the work involved in building it!

    2. You will not see any decrease in performance unless you are running additional queries to log additional data (like a query to get the name of the user running the plugin). In this case, it usually works best to add a flag to the Secure Settings of the plugin, that allows you to control whether or not it's worth the additional logging, for whatever it costs you in performance. So usually you have the flag disabled, but then if you're having some system issues, you can enable it through the plugin registration tool.

PowerObjects Recommends