SharePoint Workflow Architecture – Part 3

First published on TECHNET on Mar 12, 2013

This blog post is a contribution from Andy Li, an Escalation Engineer with the SharePoint Developer Support team.

Andy is one of the Escalation Engineer with the SharePoint Developer Support team.  The series of posts on Workflows are his contribution for the community to better understand the internals of workflow runtime and how it interacts with SharePoint.

If you missed the first two parts of this SharePoint Workflow Architecture series, below are links to quickly navigation to them.

SharePoint Workflow Architecture – Part 1

SharePoint Workflow Architecture – Part 2

Locked/Stuck Tasks

Locked tasks or stuck tasks are one of the most common issues many people have seen in workflows.  People ask me the same question when they have a locked task – how to unlock it? My answer has always been: why is the task locked in the first place?  Lot of people don’t really understand what’s causing the task to be in the locked state and simply try to unlock it and hope that will solve the problem with the workflow.  The fact is that might only make the problem worse!

There is actually a very popular “unsupported” way to unlock a task.  Essentially, the way it unlocks the task is to update the “WorkflowVersion” column for the task to “1” (we mentioned it in an earlier post that “1” means unlocked).  The problem with this workaround is that it doesn’t know what has happened with the workflow instance, where the workflow instance stopped and whether the workflow is expecting an update from the task you just unlocked etc.,

So, let’s go over it again and see how a task gets into the “stuck” or “locked” state.  First of all, we already know that the task will be in the locked state once a user submits the task from the task form.  The “locked” state will remain until the workflow instance processes the OnTaskChanged event (if you still don’t understand why, read Part 1 of this series).  So, if you are trying to re-submit the task via code or UI, you will get the exception that the task is currently being locked and you wait for hours or days and try to resubmit it and again you get the same exception.  Why?

Here is why:

#1 The ItemUpdated event has not been processed by the workflow instance yet.  So the task has to remain in the “locked” state.

#2 The ItemUpdated event has never reached the workflow engine (EventDeliveryFailedException).  Again, the workflow has not processed the event yet so that task has to remain in “locked” state.

#3 The workflow has processed the ItemUpdated event, BUT the task is not unlocked as it’s supposed to.

#1: Let’s step back a little bit to understand what happens when a user submits the task.  First of all, we know that an event receiver will be fired.  And it will try to deliver the event to workflow.  SPWorkflowManager needs to load the workflow instance into the runtime to deliver the event.  However, if the workflow instance is currently locked then SPWorkflowManager will not be able to deliver it.  A WorkItem will be queued in content database (ScheduledWorkItems table) and timer job can pick it up for re-delivery.  If timer service or timer job is not running then nobody will pick up the work item.

#2: EventDeliveryFailedException is the most famous (of infamous) exception in workflow.  There are actually a couple of different variations to this exception depending on its inner exception.  The following are the most common ones:

EventDeliveryFailedException with QueueNotFound

Let’s talk about this one (QueueNotFound) first.  QueueNotFound is a workflow runtime exception.  It basically means, that workflow is not waiting for the event you are trying to deliver to it.  In other words, it means the workflow is not waiting on anything on the task that you are submitting.  It might also mean that the workflow is waiting on task A, but you are submitting task B.  Basically, the workflow instance is not getting what it wants

So what happened?  Here are a couple of reasons that could cause this problem:

1. The workflow instance was not properly persisted.  The workflow usually will be persisted after it has no more work to do.  Especially, when it reaches OnTaskChanged activity.  The persistence service will try to save the workflow instance to the content database.  If things go wrong during the persistence process, the state of the workflow instance will be in the previous saved state, which is completely wrong.  If you have created a new task in the workflow, it has no idea about that because the state of the workflow instance is not saved.  It’s like the workflow time travels back to a point where the task has not been created yet.  Now, you are trying to submit a task that the workflow has no idea about.  So, EventDeliveryFailedException with QueueNotFound is the exception you will get.

2. The other scenario is that the workflow seems to be waiting for task A.  But you are submitting task B.  What might have happened is that the correlation parameters are messed up.  Remember that TaskId parameter you have to setup for each task you are tracking in the workflow? Yes, that is the identifier for the conversation on the task.  Each CreateTask and OnTaskChanged pair needs to have a unique TaskId which should be different from the other pairs.  One of the most common issues we see is that people use a shared variable in the workflow class to create the TaskId for each pair of CreateTask/OnTaskChanged.  There is no problem if your tasks are running sequentially.  But if the tasks will be run in parallel, you will definitely have problems with this design.  A shared variable between the tasks could cause race condition.  A TaskId for task A could be read and assigned to task B by workflow runtime (since it’s parallel) at the same time.  The chances of running into this problem may be low since it’s a race condition.  But if you are getting some random EventDeliveryFailedException once in a while, you’d better check if you are using a shared TaskId.

3. Before August 2011 CU for SharePoint 2010, there were some issues with the way SharePoint processes events.  And it could cause the workflow being persisted into a wrong state.  After August 2011 CU, the event processing is more robust although you might experience some delay in the event processing.  So, make sure you are at least on August 2011 CU if you are running out of options.

EventDeliveryFailedException with NullReferenceException

Notice that call stack says it failed on “SPWorkflowHostServiceBase.LoadInstanceData” method.  This is part of SharePoint persistence service.  SharePoint workflow runtime needs to load the workflow instance into memory before it can be delivered to the event.  This exception indicates that the workflow instance may not be persisted correclty as some objects seem to be null.  In August 2011 CU, we added more ULS logs for diagnosing issues with persistence service.  The following is an example.  So if you are not sure if your workflow has any issue with persistence, look for the following message in the ULS logs.

One of the causes of this exception is that the workflow was taking too long to finish.  There is a hard-coded threshold in SharePoint that if the workflow is taking more than 20 minutes to reach the next persistence point, its state could be re-set by the fail-over timer job.  We mentioned earlier that this timer job is used to determine if a workflow has died half way through.  If so, it’ll re-set its state.  The way the fail-over timer job detects the dead workflow is to check how long the workflow has been running.  Because most workflows should be able to complete its work within a couple of minutes or even seconds, so if a workflow status in database shows it has been running more than 20 minutes, it’s likely that it’s not running at all.

Analyzing Log Files

Workflow runtime trace and ULS logs are the most commonly used logs for troubleshooting workflow issues.

Workflow Runtime Trace

To enable workflow logging, you can use the configuration file to create output of Windows Workflow Foundation logging information to help in debugging scenarios.  Windows Workflow Foundation uses the configuration format that was introduced in the Microsoft .NET Framework 2.0.  The following examples show how to enable logging information for several Windows Workflow Foundation namespaces.

To use a configuration file to configure the workflow runtime engine for your SharePoint workflow, you first need to figure out what are the processes that may run the workflow.  W3wp.exe may be the one that comes into your mind, but don’t forget the timer service which also runs workflow.  If you don’t have a OWSTIMER.exe.CONFIG file yet, you can manually create one under the 14\Bin folder.

Here’s an example: An absolute path is specified in the initializeData attribute.  Also, some additional options are specified by using the following traceOutputOptions attributes: ProcessId and DateTime.

If these attributes are being used for a web application and if multiple instances of w3wp.exe are running, each attribute will create its own trace file.  In this scenario, in addition to the WFTrace.log file, you will have files that are named <GUID>WFTrace.log.

traceOutputOptions is used by the trace listener to determine which options or elements should be included in trace output.  In most cases, DateTime and ProcessId should be good enough.  You can also add “Callstack” to it, which will give more information about the context of the log entry.

ULS Logs

To enable verbose log for workflow, go to Central Administration site, then click Monitoring on the left navigation.  Click on Configure diagnostics logging.  Check General, Timer and Workflow Infrastructure under the SharePoint Foundation category and select Verbose in the least critical event to report to trace log.  The reason we want to enable “General” is because most of the event receiver related logs are under “General” category and it’s very useful when troubleshooting issues with the event delivery pipeline.

Analyzing ULS Logs

Most of workflow failures are associated with some sort of exception and you should be able to find the exceptions in the ULS logs.  Sometimes, the workflow appears fine on the UI, for example, the workflow status may show “In Progress” on the UI, but some of its tasks are locked.  Now, it’s time to search ULS logs to see if there’s any exception for that particular workflow instance.  The call stack associated with the exception in the ULS logs should be able to tell you what has happened on the instance and where that happened.

Each ULS log has a unique tag associated with it.  For example, “936m” is the unique tag for all “Events Successfully delivered to Instance: <InstanceId>”.

The following table shows the most common workflow error and exception that may be shown in the ULS log.

In August 2011 CU and February 2012 CU for SharePoint 2010, we add more ULS log for diagnosing workflow issues.  And they all show as “0000” on the tag.  These logs have been very useful in troubleshooting some complicated issues.

I included an example to show how to read these messages to understand what’s going on with the workflow instance.  This example, is based on the SharePoint 2010 Approval workflow template with a single task in it.  The workflow completed successfully after the task has been approved.  For each log, I included a note that explains what has just happened on the workflow instance (below).

Filtered based on workflow InstanceID

(Note that the following logs only included the logs that are filtered based on the workflow Instance ID: 84963525-6500-492a-9586-975ba07c2a19).

This is the very first log of the workflow. The reason why it seems to be trying to delivery an event is because of the OnWorkflowActivated event. As you recall, OnWorkflowActivated activity is the very first activity required for SharePoint workflow flow. It is essentially a HandleExternalEventActivity which is waiting for the initialization data from SharePoint workflow runtime. So that’s right, the very first thing on a SharePoint workflow is to deliver the initialization data to the workflow instance. Before the event delivery, we en-queue it in content database first. That’s what has happened.

En-queue completed and now we started processing the event.

Now we are processing the OnWorkflowActivated event.

The previous four logs are for setting up event receivers on the Task List. The List ID on the log suggests this is the Task list. Because I created a task in the workflow, SharePoint subscription service will set up the event receiver for each event type: ItemAdded, ItemUpdating, ItemUpdated and ItemDeleted. Note that ItemUpdated is the one that will trigger OnTaskChanged activity in the workflow.

This event receiver is for the document on which I started the workflow. The purpose of this is to listen to the “ItemDeleted” event where the workflow can respond to stop the workflow.

Workflow got no more work after the task has been created and started waiting on the OnTaskChanged activity. At this point, persistence is being called and the workflow state is saved to content database.

This log shows the persistence service successfully save the workflow state into content database.

This is the end of the OnWorkflowActivated event delivery. This seems to be too late as lots of things have already happened. Yes, but the whole thing started with delivering the very first event (OnWorkflowActviated), this marks the end of the event lifecycle.

We got this log right after the user approved the task. Now we are trying to raise the ItemUpdated (OnTaskChanged) event to the workflow instance.

Again, en-queuing the event first to content database.

Start processing the OnTaskChanged event.

This is just a notification that this is non-timer event. Timer events are events such as “Delay”, “DelayFor”, etc.

Persistence service loaded the workflow instance from database into memory. This process de-serializes the workflow state and loads it into workflow runtime. Notice the size of the instance data (38253) is exactly the same with the one we persisted in previous log.

Workflow instance finished processing the OnTaskChanged event, now persistence service is being called again to save the workflow state back to content database.

This notifies that the workflow has been successfully persisted.

Again, this marks the end of the ItemUpdated (OnTaskChanged) event lifecycle.

Other Logs for Event Pipeline

Some of the logs on the event delivery pipeline are not in the Workflow Infrastructure category. But these are the ones you need to look for:

The update on a workflow update starts with SPWorkflowTask.AlterTask() API.

This is a SharePoint internal call that’s making the changes to the list item associated with the task.

Check and fire Item event receiver, as its name suggests. (this is for Synchronous event receivers).

Start firing item event receivers.

Execute Synchronous Item event receivers. For example, ItemUpdating event.

Check and fire Item event receiver, as its name suggests. (This is for Asynchronous event receivers).

Fire Asynchronous item event receivers.

Fire ItemUpdated event on the task.

Workflow event receiver is being called and it will try to deliver the event to workflow instance through SPWorkflowManager.

Analyzing Workflow Runtime Trace

Workflow trace may look overwhelming when you look at it the first time. The key is to read the actual workflow logic and understand what sequence of the activities and then try to find the same activity flow in the trace file.

The next is a full walk through about how to read the workflow trace. It’s based on the previous sample workflow which has a CreateTask activity, an OnTaskChanged activity and a CompleteTask activity at the end. The OnTaskChanged activity is wrapped in a While activity which will end when the Task is marked as “100%” Complete.

NOTE : A note has been included after each highlighted log.

Note that this trace only included the logs for the workflow instance that we are analyzing. You should always filter the trace based on the instance ID because it would be very distracting when you look at a trace that has multiple instances running.

This is the start of the workflow.

“Workflow1” is the name of the workflow template. “Adding Context 1” basically means this is the current activity we are executing.

“Creating new Queue” basically is a workflow runtime language, it means that an “event sink” has been created for OnWorkflowActivated activity. As you recall, OnWorkflowActivated is an event defined on ISharePointService.

SharePoint Workflow has just delivered the OnWorkflowActivated event to workflow runtime, that’s why we are seeing “Firing event OnWorkflowActivated”. Go back and check the ULS log and see if you find the logs for delivering “OnWorkflowActivated” event.

The activity onWorkflowActivated1 is being executed by workflow runtime, because its status changed from “Initialized” to “Executing”.

This indicates that the OnWorkflowActivated activity has finished. Its status changed from “Executing” to “Closed”.

onWorkflowActivated1 activity finished successfully.

Do you see the next activity on the workflow template? Yes its name is sequenceActivity1. Notice that createTask1 and onTaskChanged1 are child activities of sequenceActivity1.

createTask1 is the first Child activity of sequenceActivity1.

As we mentioned earlier, A “Queue” in the language of workflow runtime is similar to an “event sink”, since the task is associated with an OnTaskChanged activity we’ll then need to set up a Queue for it. The Queue will be called back when workflow runtime receives the event from SharePoint. Notice that the CorrelationValue is the TaskId you created on createTask1_Invoking() method.

createTask1 completed.

Start executing the next activity: whileActivity1.

Start executing onTaskChanged1 activity.

Subscribe 'onTaskChanged1' activity to QueueitemAvailable, this basically set up the event sink with the workflow runtime so that when workflow runtime receives the event from host application, it will raise the event to the onTaskChanged1 activity.

The above five highlighted logs shows that the workflow instance has no more work except waiting for the event to come back. It’s time to persist and unload the workflow instance. Notice that last highlight log says “Serialized a <workflow class> to length 9045”. 9045 is the size of the workflow instance data. You should still remember that in ULS log there is a log that shows the same instance size.

(NOTE: the full ULS log for this particular instance was not included in this document).

Workflow instance is removed from workflow runtime.

One minute later we are loading the instance from content database back into workflow runtime. This is after the user submitted the task through UI and the event has already been delivered half through the pipeline.

Now you see the same size 9045, and this corresponds to the ULS log:

(NOTE: the full ULS log for this particular instance was not included in this document).

When analyzing ULS log and workflow trace, always verify the size of the workflow instance to ensure that workflow instance runtime is loading matches the one it was persisted. An unmatched instance sizes means issues might have occurred with the persistence service.

Loading the workflow instance and adding the current context activities. onTaskChanged1 is where we left off.

The event finally was raised to OnTaskChanged activity.

onTaskChanged1 activity is inside a While Loop, so we need to re-subscribe the event every time after it has been raised.

onTaskChanged1 activity finished.

whileActivity1 activity finished.

All child activities of sequenceActivity1 finished. Now sequenceActivity1 is also finished.

Start executing completeTask1 activity.

Done executing completeTask1.

Done executing the entire workflow.

Removing the workflow instance from workflow runtime.

Conclusion

This concludes this three part series on SharePoint Workflow Architecture and troubleshooting.  Hope you found this as a helpful resource.  Do drop us a line if you have any comments or questions.