Archiv für Oktober 2011

SharePoint Workflow Debugging & Troubleshooting

22 Oktober 2011

Developing workflows in SharePoint should be so easy that also a power user is able to do it. I run a lot of training in this area and I stay in contact with my customers very often, so I can see what they really build and what kind of problems they may have to face.

This is where the trouble begins. It is not at all an easy task to identify errors in the system when you run into them. You can discover some error messages in the UI but most of them are in the logs or EventLog only. For bigger companies it is not a standard process to get access to this kind of information, not even for a power user.

If you develop the workflows on your local developing system, before moving to the stage or production, you can configure a powerful additional tracing of the execution of the workflow foundation engine. With this information you will be able to understand how the engine is really executing the workflow, when the system is going to hydrate or dehydrate the workflows. This will enhance the level of understanding and also give you additional exception messages which are a level below the workflow foundation layer. For example you will see an SQL exception about a lock instead of generic “error occurred” message in the SharePoint UI or the logs.

To activate it, you must add this XML configuration to the web.config of your SharePoint WFE. You can add it e.g. bellow </system.web> node. In the customListener you can define the name of the file, where the trace data will be logged:

</system.web>

<!– START –>

<system.diagnostics>

<switches>

<add
name=System.Workflow LogToTraceListeners
value=1 />

<add
name=System.Workflow.Runtime.Hosting
value=All />

<add
name=System.Workflow.Runtime
value=All />

<add
name=System.Workflow.Runtime.Tracking
value=All />

<add
name=System.Workflow.Activities
value=All />

</switches>

<trace
autoflush=true
indentsize=4>

<listeners>

<add
name=customListener
type=System.Diagnostics.TextWriterTraceListener
initializeData=WFTrace.log />

</listeners>

</trace>

</system.diagnostics>

<!– END –>

<system.webServer>

 

Let’s now see the tracer in action. We start with the following scenario. For a leave approval we have a form as a SharePoint list. The applicant creates a new form and fills it out. After this point it should be not possible for this person to manipulate the form and e.g. change the date. To do so we use a custom workflow action – Set Item Permissions. You can download it for SharePoint Designer from codeplex http://spdactivities.codeplex.com/. If you are using Nintex Workflow you can just choose the Set Item Permission Action. We start with a very simple workflow:

In the “Set Item Permissions” we configure it as follows:

In this case we remove all rights and give full control rights to only one user – User1.

To start the workflow we sign in as an another SharePoint user – User2.

If we run this workflow, the workflow is executed with the rights of User2. So we can expect, that the workflow will run into errors an throw an access denied exception. But something different is happening! Actually we are able to change the value of the form and the element disappears from the list, because we as User2 don’t have the permission even to see it. Very strange!

To understand this behavior we can look at what the workflow engine is doing. We now analyze the run of this workflow instance in WFTrace.log
(if you have the same configuration as I do in the example, you will find the file in the same folder as the web.config).

 

I have removed all the “noise” from the file and just left the action which you can also see in the workflow history:

ManualWorkflowSchedulerService: Running workflow 4a2e76af-278b-4f2b-b4af-9f901445b1a6

Workflow Runtime: Scheduler: InstanceId: 4a2e76af-278b-4f2b-b4af-9f901445b1a6 : Done with running scheduled entry: SubscriptionEvent((1)ROOT, ActivityStatusChange(’(1)setItemPermissions1‘, Closed, Succeeded))

pending work hc 48569549 added workItem hc 2904135

Activity Status Change – Activity: updateItemActivity1 Old:Initialized; New:Executing

pending work hc 21962844
added workItem hc 54551106

Activity Status Change – Activity: writeToHistoryListActivity1 Old:Initialized; New:Executing

pending work hc 21962844 added workItem hc 56161022

WorkflowExecutor: Calling CommitTransaction for instance 4a2e76af-278b-4f2b-b4af-9f901445b1a6 hc 36692160

… pending work hc 21962844 added workItem hc 18298772

… pending work hc 21962844 added workItem hc 54551106

… pending work hc 21962844 added workItem hc 56161022

… pending work hc 48569549 added workItem hc 2904135

… pending work hc 50487737 added workItem hc 60477497

As you can see the workflow foundation puts ALL the Microsoft action in one batch hc 21962844
and all Nintex a
ction in another one hc 48569549. The idea behind this is to improve the performance and cumulate the executions. It works, as long as you are running Microsoft as the only action. If you mix it with your custom action, like here with Nintex action, you can get into trouble.

Nintex adds an action “commit pending changes” to overcome this issue. To have a correctly running workflow you must change the design of the workflow, too:

What we can see now. The workflow runs into an error as expected before:

What happened behind the scene?

System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: f920b7a1-cf74-44ef-b79c-c4efd3a14fa1 : Running scheduled entry: ActivityOperation((1)setItemPermissions1, Execute)

… pending work hc 48569549 added workItem hc 1221152

: Workflow Runtime: WorkflowExecutor: Calling SaveWorkflowInstanceState for instance f920b7a1-cf74-44ef-b79c-c4efd3a14fa1 hc 8536155

System.Workflow.Runtime.Hosting Information: 0 : Serialized a System.Workflow.ComponentModel.ActivityExecutionContextInfo with id f920b7a1-cf74-44ef-b79c-c4efd3a14fa1 to length 8918. Took 00:00:00.0087939.

0 : Workflow Runtime: WorkflowExecutor: Calling CommitTransaction for instance f920b7a1-cf74-44ef-b79c-c4efd3a14fa1 hc 8536155

System.Workflow.Runtime Information: 0 : pending work hc 58093310 added workItem hc 6984404

System.Workflow.Runtime Information: 0 : pending work hc 48569549 added workItem hc 1221152

System.Workflow.Runtime Information: 0 : pending work hc 50487737 added workItem hc 18578734

System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: f920b7a1-cf74-44ef-b79c-c4efd3a14fa1 : Scheduling entry: ActivityOperation((1)updateItemActivity1, Execute)

System.Workflow.Runtime Critical: 0 : Uncaught exception escaped to the root of the workflow. In instance f920b7a1-cf74-44ef-b79c-c4efd3a14fa1 in activity Inner exception: System.ArgumentException: Item does not exist. It may have been deleted by another user. at Microsoft.SharePoint.SPList.GetItemById(String strId, Int32 id, String strRootFolder, Boolean cacheRowsetAndId, String strViewFields, Boolean bDatesInUtc) at Microsoft.SharePoint.Workflow.SPWinOEWSSServ

As you can see (2) it forces the workflow engine to call the CommitTransaction after the Set item permission action. What does this mean?

The workflow engine dehydrates (2) and hydrates the workflow instance to and from the SQL database! After this step the workflow continues with the next action Update Item.

You must be aware of this kind of effects when you design your workflow and use the tracing possibility described in this post, if you develop workflow to validate the correct execution.

 

Bookmark and Share