SharePoint Workflow Architecture – Part 3

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:

 Engine RunWorkflow: System.Workflow.Activities.EventDeliveryFailedException:
 Event "OnTaskChanged" on interface type "Microsoft.SharePoint.Workflow.ITaskService" for instance id "84f908b6-0357-497c-b7cc-8021798dc706" cannot be delivered. 
 ---> System.Workflow.Runtime.QueueException: Event Queue operation failed with MessageQueueErrorCode QueueNotFound for queue 'Message Properties  Interface Type:Microsoft.SharePoint.Workflow.ITaskService  Method Name:OnTaskChanged  CorrelationValues:  ff5aa7b7-b6e4-4efb-84ef-27750b17b8ca  '.
 at System.Workflow.Runtime.WorkflowQueuingService.GetQueue(IComparable queueID)
 Windows SharePoint Services Workflow Infrastructure Engine RunWorkflow: 
 System.Workflow.Activities.EventDeliveryFailedException: Event "OnTaskChanged" on interface type "Microsoft.SharePoint.Workflow.ITaskService" for instance id 
 "4565fe7f-6043-4e8b-8896-4565fe7f9058" can not be delivered. ---> 
 System.NullReferenceException: Object reference not set to an instance of an object. at Microsoft.SharePoint.Workflow.SPWorkflowHostServiceBase.LoadInstanceData (Guid instanceId, Boolean& compressedData)
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 Smile

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.

 Failed to persist workflow instance: 3c489d77-355c-4beb-86d4-1f106f26113c with error code: 5,
 instance data size: 34505, internal state: Running, processing id: 4db2b5e9-cf02-479f-83fc-db106a432ba4    15bfccd3-663b-449e-8d37-113494e4f892

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.

 <?xml version="1.0" encoding="utf-8"?>
 <configuration>
   <system.diagnostics>
     <sources>
       <source name="System.Workflow.Runtime" >
         <listeners>
           <add name = "System.Workflow"/>
         </listeners>
       </source>
       <source name="System.Workflow.Runtime.Hosting">
         <listeners>
           <add name="System.Workflow"/>
         </listeners>
       </source>
       <source name="System.Workflow.Activities">
         <listeners>
           <add name="System.Workflow"/>
         </listeners>
       </source>
     </sources>
     <sharedListeners>
       <add name="System.Workflow"
            type="System.Diagnostics.TextWriterTraceListener"
            initializeData="d:\_temp\WFTrace.log"
            traceOutputOptions="DateTime,ProcessId"/>
     </sharedListeners>
     <switches>
       <add name="System.Workflow.LogToTraceListeners" value="1"/>
       <add name="System.Workflow.Runtime" value="All" />
       <add name="System.Workflow.Runtime.Hosting" value="All" />
       <add name="System.Workflow.Runtime.Tracking" value="All" />
       <add name="System.Workflow.Activities" value="All" />
       <add name="System.Workflow.Activities.Rules" value="All" />
     </switches>
   </system.diagnostics>
 </configuration>

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>”.

 07/25/2011 12:31:01.68
 OWSTIMER.EXE (0x1DCC)
 0x1E34
 SharePoint Foundation
 Workflow Infrastructure
 936m
 Verbose
 RunWorkflow: Events successfully delivered to Instance: e63dcf89-5cd5-4121-8302-58063851e903, Association: dde85862-a347-4ab2-9978-f8fbaf7d965f, BaseTemplate: 62506157-6fad-4127-8b0f-6f37fa023000    2f8a3470-d977-4b09-b51b-5770bf6e86b4

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

ULS tag

Location and Log

tag_72fq

Location: SPWorkflowManager.StartWorkflow()

Message: "Start Workflow: <exception message>”

tag_72fr

Location: SPWorkflowManager.SaveInstanceData()

Message: "Workflow Save Instance: <exception message>”

tag_98d6

Location: SPWorkflowManager.SaveInstanceData()

tag_72fs

Location: SPWorkflowManager.RunWorkflow()

Message: "RunWorkflow: <exception message>"

tag_98d7

Location: SPWorkflowManager.RunWorkflow()

Message: An entry is logged into HistoryList

tag_72fu

Location: SPWorkflowManager.LoadPluggableClass

Message: “Load Workflow Class: <exception message>"

tag_72fr

Location: SPWorkflowManager.AutoStartWorkflow

Message: “Declarative workflow may fail to start because it was trying to impersonate the workflow author, but that user does not exist on this site."

tag_72fv

Location: SPWorkflowManager.AutoStartWorkflow

Message: “AutoStart Workflow: <exception message>"

tag_7fbw

Location: SPWorkflowManager.DelaySTartworkflow

Message: "DelayedStart Workflow: <exception message>”

tag_72et,

Location: SPWinOeHostServices.CreateSubscription

tag_72eu,

Location: SPWinOeHostServices.DeleteSubscription

tag_72ev

Location: SPWinOETaskService.CreateTask

tag_72ew,

Location: SPWinOETaskService.CreateTaskWithContnetType

tag_72ez,

Location: SPWinOETaskService.DeleteTask

tag_72f0,

Location: SPWinOETaskService.CompleteTask

tag_72f1,

Location: SPWinOETaskService.RollBackTask

tag_72f2

Location: SPWinOETaskService.SendEmail

tag_75yn

Location: SPWinOEHostService.LoadWorkflowAssembly

“Load Workflow Assembly: %s"”

tag_88xr,

Location: SPWinOEHostService.TerminateWorkflow

“WinWF Internal Error, terminating workflow Id# <InstanceID>"

tag_98d4,

Location: SPWinOEHostService.TerminateWorkflow

tag_98d5

Location: SPWinOEHostService .ExceptionNotHandled

tag_72eo

Location: SPWinOEHostService .DehydrateInstance

Message: “DehydrateInstance: <Exception Message>”

tag_72ep

Location: SPWinOEHostService .WorkItemDequeue

Message: “Workflow WorkItem Dequeue: <Exception Message>"

tag_936l

Location: SPWinOeEngine.RunWorkflow

Message: "Engine RunWorkflow: <Exception Message>",

tag_936m

Location: SPWinOeEngine.RunWorkflow

Message: "RunWorkflow: Events successfully delivered to Instance: <InstanceID>

0000

"In workflow failover job, unlocking workflow instance: {0}, processing id: {1}"

0000

In workflow failover job, failover in progress work items for workflow instance: {1}, processing id: {1}

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.

ULS tag

Location and Log

0000

"Running timer event for workflow instance <InstanceID>”

0000

“Running non-timer event for instance <InstanceID>”

0000

"After RunWorkflow() the instance is still running. Calling TryUnload() on workflow instance: < InstanceID>”

0000

“Processing {0} events for workflow instance: < InstanceID>, processing id: <ProcessingID>”

0000

"Stopped processing events for workflow instance: <InstanceID> because the instance is unlocked."

0000

"Processing event <eventName> with id <EventId> for workflow instance: < InstanceID>, processing id: <ProcessingID>”

0000

"In RaiseEvent(), calling RunWorkflowElev for instance < InstanceID>, event type: <EventType>"

0000

"Calling RouteWorkflowEvent() on list <ListId>, item <ItemID> for event type: <EventType>”

0000

"In Workflow event receiver, ItemUpdating()");

0000

"In ItemUpdated() call on workflow event receiver for list id: <ListId>, item id: <ItemID>”

0000

"Setting up workflow event receiver for instance: <InstanceID> on list <ListID>"

0000

"Loaded instance data for instance: <InstanceID>, data size: <Size>, processing id: <ProcessingID>"

0000

"Calling SaveInstanceData for workflow instance:<InstanceID>; instance data size: <Size>, internal state: <InternalState>, processing id: <ProcessingID>"

0000

"Failed to persist workflow instance: <InstanceID> with error code: <InstanceID>,instance data size: <Size>, internal state: <InternalState>, processing id: <ProcessingID>"

0000

"Successfully persisted workflow instance: <InstanceID> with error code: <ErrorCode>, instance data size: <Size>, internal state: <InternalState> processing id: <ProcessingID>"

0000

"Unlocking instance: <InstanceID> with processing id: <ProcessingID> because its internal state <InternalState> is completed or terminated"

0000

"In RunWorkflowElev(), Enqueue pending event: <Event> for instance: <InstanceID>"

0000

"In RunWorkflowElev(), begin processing events for instance: <InstanceID>”

0000

"Updating workflow task with id <TaskID> on list <ListID> in AlterTask()"

0000

"In fireItemEvent(), for list <ListID>, and item: <ItemID>",

0000

"In fireSyncItemEvent(), calling ExecuteItemEventReceivers()")

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).

 06/26/2012 16:05:00.59
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 In RunWorkflowElev(), Enqueue pending event: bf3ab7d2-cc40-3634-a4d6-1978b43af379 for instance: 84963525-6500-492a-9586-975ba07c2a19    53bffe51-5d04-448a-a592-2ec318f9d13f

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.

 06/26/2012 16:05:02.12    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 In RunWorkflowElev(), begin processing events for instance: 84963525-6500-492a-9586-975ba07c2a19    53bffe51-5d04-448a-a592-2ec318f9d13f
  
  
 06/26/2012 16:05:19.27    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Processing 1 events for workflow instance: 84963525-6500-492a-9586-975ba07c2a19, processing id: 9e4dbed4-55af-4b85-907a-a1e2d6761c58    53bffe51-5d04-448a-a592-2ec318f9d13f

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

 06/26/2012 16:05:19.27    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Processing event OnWorkflowActivated with id 00000000-0000-0000-0000-000000000000 for workflow instance: 84963525-6500-492a-9586-975ba07c2a19, processing id: 9e4dbed4-55af-4b85-907a-a1e2d6761c58    53bffe51-5d04-448a-a592-2ec318f9d13f

Now we are processing the OnWorkflowActivated event.

 06/26/2012 16:05:26.25    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Setting up workflow event receiver for instance: 84963525-6500-492a-9586-975ba07c2a19 on list 1a9f51bb-d41e-457c-8998-a443de8e02e9    53bffe51-5d04-448a-a592-2ec318f9d13f
  
  
  
 06/26/2012 16:05:26.26    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Setting up workflow event receiver for instance: 84963525-6500-492a-9586-975ba07c2a19 on list 1a9f51bb-d41e-457c-8998-a443de8e02e9    53bffe51-5d04-448a-a592-2ec318f9d13f
  
  
  
 06/26/2012 16:05:26.26    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Setting up workflow event receiver for instance: 84963525-6500-492a-9586-975ba07c2a19 on list 1a9f51bb-d41e-457c-8998-a443de8e02e9    53bffe51-5d04-448a-a592-2ec318f9d13f
  
  
  
 06/26/2012 16:05:26.26    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Setting up workflow event receiver for instance: 84963525-6500-492a-9586-975ba07c2a19 on list 1a9f51bb-d41e-457c-8998-a443de8e02e9    53bffe51-5d04-448a-a592-2ec318f9d13f

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.

 06/26/2012 16:05:26.54    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Setting up workflow event receiver for instance: 84963525-6500-492a-9586-975ba07c2a19 on list 4a8a416b-c92b-4cfc-82f9-e5e99c5bc871    53bffe51-5d04-448a-a592-2ec318f9d13f

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.

 06/26/2012 16:05:27.29    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Calling SaveInstanceData for workflow instance: 84963525-6500-492a-9586-975ba07c2a19, instance data size: 38253, internal state: Locked, Running, NotStarted, processing id: 9e4dbed4-55af-4b85-907a-a1e2d6761c58    53bffe51-5d04-448a-a592-2ec318f9d13f

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.

 06/26/2012 16:05:27.35    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Successfully persisted workflow instance: 84963525-6500-492a-9586-975ba07c2a19 with error code: 0, instance data size: 38253, internal state: Locked, Running, NotStarted, processing id: 9e4dbed4-55af-4b85-907a-a1e2d6761c58    53bffe51-5d04-448a-a592-2ec318f9d13f

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

 06/26/2012 16:05:27.41    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 936m    
 Verbose    
 RunWorkflow: Events successfully delivered to Instance: 84963525-6500-492a-9586-975ba07c2a19, Association: 8dc4f282-d366-4e7f-838d-1838bb7fd829, BaseTemplate: 8ad4d8f0-93a7-4941-9657-cf3706f00409, processing id: 9e4dbed4-55af-4b85-907a-a1e2d6761c58    53bffe51-5d04-448a-a592-2ec318f9d13f

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.

 06/26/2012 16:05:52.67    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 In RaiseEvent(), calling RunWorkflowElev for instance 84963525-6500-492a-9586-975ba07c2a19, event type: Microsoft.SharePoint.Workflow.ITaskService

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.

 06/26/2012 16:05:52.67    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 In RunWorkflowElev(), Enqueue pending event: ceb27b99-ec4c-3b88-81f4-343de4d3ed0d for instance: 84963525-6500-492a-9586-975ba07c2a19

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

 06/26/2012 16:05:52.68    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 In RunWorkflowElev(), begin processing events for instance: 84963525-6500-492a-9586-975ba07c2a19    
  
  
 06/26/2012 16:05:52.68    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Processing 1 events for workflow instance: 84963525-6500-492a-9586-975ba07c2a19, processing id: 973d7273-526b-47a9-85f4-337f9fe82751
  
  
 06/26/2012 16:05:52.68    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Processing event OnTaskChanged with id 00000000-0000-0000-0000-000000000000 for workflow instance: 84963525-6500-492a-9586-975ba07c2a19, processing id: 973d7273-526b-47a9-85f4-337f9fe82751

Start processing the OnTaskChanged event.

 06/26/2012 16:05:52.68    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation   
 Workflow Infrastructure    
 0000    
 Verbose    
 Running non-timer event for instance 84963525-6500-492a-9586-975ba07c2a19, internal state: Locked, Running, processing id: 973d7273-526b-47a9-85f4-337f9fe82751

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

 06/26/2012 16:05:52.69    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Loaded instance data for instance: 84963525-6500-492a-9586-975ba07c2a19, data size: 38253, processing id: 973d7273-526b-47a9-85f4-337f9fe82751

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.

 06/26/2012 16:05:53.76    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Calling SaveInstanceData for workflow instance: 84963525-6500-492a-9586-975ba07c2a19, instance data size: 0, internal state: Locked, Running, processing id: 973d7273-526b-47a9-85f4-337f9fe82751

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

 06/26/2012 16:05:53.84    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Successfully persisted workflow instance: 84963525-6500-492a-9586-975ba07c2a19 with error code: 0, instance data size: 0, internal state: Locked, Running, processing id: 973d7273-526b-47a9-85f4-337f9fe82751

This notifies that the workflow has been successfully persisted.

 06/26/2012 16:05:53.86    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 936m    
 Verbose    
 RunWorkflow: Events successfully delivered to Instance: 84963525-6500-492a-9586-975ba07c2a19, Association: 8dc4f282-d366-4e7f-838d-1838bb7fd829, BaseTemplate: 8ad4d8f0-93a7-4941-9657-cf3706f00409, processing id: 973d7273-526b-47a9-85f4-337f9fe82751

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:

 06/26/2012 16:05:52.31    
 w3wp.exe (0x27B4)    
 0x20B4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Updating workflow task with id 1 on list 1a9f51bb-d41e-457c-8998-a443de8e02e9 in AlterTask()    f3b13df8-1bb9-4aed-8faa-5a59b31bf1b0

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

 06/26/2012 16:05:52.32    
 w3wp.exe (0x27B4)    
 0x20B4    
 SharePoint Foundation    
 General    
 0000   
 Verbose    
 In SPRequest.AddOrUpdateItem(), for list {1A9F51BB-D41E-457C-8998-A443DE8E02E9}, and item: 1    f3b13df8-1bb9-4aed-8faa-5a59b31bf1b0

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

 06/26/2012 16:05:52.32    
 w3wp.exe (0x27B4)    
 0x20B4    
 SharePoint Foundation    
 General    
 0000    
 Verbose    
 In CheckandfireItemEvent(), for list item 1    f3b13df8-1bb9-4aed-8faa-5a59b31bf1b0

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

 06/26/2012 16:05:52.32    
 w3wp.exe (0x27B4)    
 0x20B4    
 SharePoint Foundation    
 General    
 0000    
 Verbose    
 In fireItemEvent(), for list Tasks, and item: 1    f3b13df8-1bb9-4aed-8faa-5a59b31bf1b0
  
  
 06/26/2012 16:05:52.32    
 w3wp.exe (0x27B4)    
 0x20B4    
 SharePoint Foundation    
 General    
 0000    
 Verbose    
 In fireSyncItemEvent(), calling ExecuteItemEventReceivers()    f3b13df8-1bb9-4aed-8faa-5a59b31bf1b0

Start firing item event receivers.

 06/26/2012 16:05:52.33    
 w3wp.exe (0x27B4)    
 0x20B4    
 SharePoint Foundation    
 General    
 0000    
 Verbose    
 Calling ExecuteItemEventReceivers() for list 1a9f51bb-d41e-457c-8998-a443de8e02e9 on item 1    f3b13df8-1bb9-4aed-8faa-5a59b31bf1b0

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

 General    
 0000    
 Verbose    
 In CheckandfireItemEvent(), for list item 1    f3b13df8-1bb9-4aed-8faa-5a59b31bf1b0

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

 06/26/2012 16:05:52.56    
 w3wp.exe (0x27B4)    
 0x20B4    
 SharePoint Foundation    
 General    
 0000    
 Verbose    
 In fireItemEvent(), for list Tasks, and item: 1    f3b13df8-1bb9-4aed-8faa-5a59b31bf1b0

Fire Asynchronous item event receivers.

 06/26/2012 16:05:52.57    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 In ItemUpdated() call on workflow event receiver for list id: 1a9f51bb-d41e-457c-8998-a443de8e02e9, item id: 1

Fire ItemUpdated event on the task.

 06/26/2012 16:05:52.58    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Calling RouteWorkflowEvent() on list 1a9f51bb-d41e-457c-8998-a443de8e02e9, item 1 for event type: ItemUpdated

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.

image

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.

 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime: Started WorkflowRuntime 023c7e83-b965-4322-a4c1-57b4303a560c
     ProcessId=5128
     DateTime=2012-06-27T00:28:46.8992124Z
 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.1062516Z
 System.Workflow.Runtime Start: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.1072282Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime dispensing resource, instanceId: 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.1091814Z
 System.Workflow.Runtime.Hosting Information: 0 : Creating instance 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
 DateTime=2012-06-27T00:28:47.6404518Z

This is the start of the workflow.

 System.Workflow.Runtime Information: 0 : Queuing Service: Creating new Queue with ID -514710269 for *PendingNotifications
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.6785392Z
 System.Workflow.Runtime.Hosting Information: 0 : TimerEventSubscriptionQueue: 64f82660-15b8-4a7e-90b7-4e054164e923 Created
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.6795158Z
 System.Workflow.Runtime Information: 0 : Adding context 1:Workflow1
     ProcessId=5128
 DateTime=2012-06-27T00:28:47.6814690Z

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

 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime:: replacing unusable executor for key 64f82660-15b8-4a7e-90b7-4e054164e923 with new one (hc: 61799993)
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.6843988Z
 System.Workflow.Runtime Information: 0 : Queuing Service: Creating new Queue with ID -528633178 for Message Properties
 Interface Type:Microsoft.SharePoint.Workflow.ISharePointService
 Method Name:OnWorkflowActivated
 CorrelationValues:
  
     ProcessId=5128
 DateTime=2012-06-27T00:28:47.7371352Z

“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.

 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime dispensing resource instanceId: 64f82660-15b8-4a7e-90b7-4e054164e923, hc: 61799993
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.7742460Z
 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=00000000-0000-0000-0000-000000000000
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.7742460Z
 System.Workflow.Runtime Stop: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.7742460Z
 System.Workflow.Activities Information: 0 : Firing event OnWorkflowActivated for instance 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
 DateTime=2012-06-27T00:28:47.8679996Z

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.

 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.8699528Z
 System.Workflow.Runtime Start: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.8699528Z
 System.Workflow.Runtime Information: 0 : Queuing Service: Enqueue item Queue ID -528633178 for Message Properties
 Interface Type:Microsoft.SharePoint.Workflow.ISharePointService
 Method Name:OnWorkflowActivated
 CorrelationValues:
  
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.8875316Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 3707448
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9041338Z
 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=00000000-0000-0000-0000-000000000000
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9060870Z
 System.Workflow.Runtime Stop: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9060870Z
 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9080402Z
 System.Workflow.Runtime Start: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9080402Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: Workflow1 Old:Initialized; New:Executing
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9217126Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: ActivityOperation((1)Workflow1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9334318Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: Schedule workflow 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9422212Z
 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=00000000-0000-0000-0000-000000000000
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9422212Z
 System.Workflow.Runtime Stop: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9422212Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: Running workflow 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9451510Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: CanRun is True
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9471042Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: Executing 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9500340Z
 System.Workflow.Runtime.Hosting Information: 0 : Running workflow 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9510106Z
 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9558936Z
 System.Workflow.Runtime Start: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:28:47.9558936Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: ActivityOperation((1)Workflow1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.0008172Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: onWorkflowActivated1 Old:Initialized; New:Executing
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.0359748Z

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

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: ActivityOperation((1)onWorkflowActivated1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.0359748Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: ActivityOperation((1)Workflow1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.0359748Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: ActivityOperation((1)onWorkflowActivated1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.0359748Z
 System.Workflow.Runtime Information: 0 : CorrelationToken initialized for workflowToken owner activity Workflow1 
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.0721090Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: onWorkflowActivated1 Old:Executing; New:Closed
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.1101964Z

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

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)onWorkflowActivated1', Closed, Succeeded))
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.1209390Z

onWorkflowActivated1 activity finished successfully.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: ActivityOperation((1)onWorkflowActivated1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1355880Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)onWorkflowActivated1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1355880Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: sequenceActivity1 Old:Initialized; New:Executing
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.1453540Z

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.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: ActivityOperation((1)sequenceActivity1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1453540Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)onWorkflowActivated1', Closed, Succeeded))     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1453540Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: ActivityOperation((1)sequenceActivity1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1453540Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: createTask1 Old:Initialized; New:Executing
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.1453540Z

createTask1 is the first Child activity of sequenceActivity1.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: ActivityOperation((1)createTask1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1453540Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: ActivityOperation((1)sequenceActivity1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1453540Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: ActivityOperation((1)createTask1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1453540Z
 System.Workflow.Activities Information: 0 : CorrelationTokenInvalidatedHandler: creating q -798539121 
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.1687924Z
 System.Workflow.Runtime Information: 0 : Queuing Service: Creating new Queue with ID -798539121 for Message Properties
 Interface Type:Microsoft.SharePoint.Workflow.ITaskService
 Method Name:OnTaskChanged
 CorrelationValues:
 b788bb83-2882-4587-b4a9-b8a3bfc7c1b9
  
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.1687924Z

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.

 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 37535352
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.2049266Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 46630754
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.2049266Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 47616313
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.2049266Z
 System.Workflow.Runtime Information: 0 : CorrelationToken initialized for taskToken owner activity Workflow1 
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.2049266Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 16973140
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.3240718Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: createTask1 Old:Executing; New:Closed
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.3445804Z

createTask1 completed.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)createTask1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.3445804Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: ActivityOperation((1)createTask1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.3445804Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)createTask1', Closed, Succeeded))
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.3445804Z
  
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: whileActivity1 Old:Initialized; New:Executing
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.3445804Z

Start executing the next activity: whileActivity1.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: ActivityOperation((1)whileActivity1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.3445804Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)createTask1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.3445804Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: ActivityOperation((1)whileActivity1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.3445804Z
 System.Workflow.Runtime Information: 0 : Adding context 2:onTaskChanged1
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.5008364Z
  
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: onTaskChanged1 Old:Initialized; New:Executing
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.5027896Z

Start executing onTaskChanged1 activity.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: ActivityOperation((2)onTaskChanged1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5027896Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: ActivityOperation((1)whileActivity1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5037662Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: ActivityOperation((2)onTaskChanged1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5037662Z
 System.Workflow.Runtime Information: 0 : WorkflowQueue:QueueItemAvailable subscribe for activity 'onTaskChanged1' with context Id 2
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5106024Z
 System.Workflow.Activities Information: 0 : CorrelationService: activity 'onTaskChanged1' subscribing to QueueItemAvailable
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.5106024Z

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.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: ActivityOperation((2)onTaskChanged1, Execute)
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.5106024Z
  
 System.Workflow.Runtime Information: 0 : Workflow Runtime: WorkflowExecutor: workflow instance '64f82660-15b8-4a7e-90b7-4e054164e923' has no work.
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5115790Z
 System.Workflow.Runtime Information: 0 : Workflow Runtime: WorkflowExecutor: Unloading instance 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5174386Z
 System.Workflow.Runtime.Hosting Information: 0 : TimerEventSubscriptionQueue: 64f82660-15b8-4a7e-90b7-4e054164e923 Suspend
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5193918Z
 System.Workflow.Runtime Information: 0 : 64f82660-15b8-4a7e-90b7-4e054164e923: Calling PerformUnloading(false): InstanceId 64f82660-15b8-4a7e-90b7-4e054164e923, hc: 61799993
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5193918Z
 System.Workflow.Runtime Information: 0 : Workflow Runtime: WorkflowExecutor: Calling SaveWorkflowInstanceState for instance 64f82660-15b8-4a7e-90b7-4e054164e923 hc 61799993
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.5359940Z
 System.Workflow.Runtime.Hosting Information: 0 : Serialized a System.Workflow.ComponentModel.ActivityExecutionContextInfo with id 64f82660-15b8-4a7e-90b7-4e054164e923 to length 9045. Took 00:00:00.0625024.
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.6141220Z

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.

 06/26/2012 16:05:27.29    
 w3wp.exe (0x27B4)    
 0x21F4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000    
 Verbose    
 Calling SaveInstanceData for workflow instance: 64f82660-15b8-4a7e-90b7-4e054164e923, instance data size: 9045, internal state: Locked, Running, NotStarted, processing id: 9e4dbed4-55af-4b85-907a-a1e2d6761c58    53bffe51-5d04-448a-a592-2ec318f9d13f

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

 System.Workflow.Runtime Information: 0 : pending work hc 63891231 added workItem hc 15165310
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.6150986Z
 System.Workflow.Runtime Information: 0 : Workflow Runtime: WorkflowExecutor: Calling CommitTransaction for instance 64f82660-15b8-4a7e-90b7-4e054164e923 hc 61799993
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.6209582Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 3707448
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.6824840Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 37535352
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.6824840Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 46630754
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.6824840Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 47616313
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.6824840Z
 System.Workflow.Runtime Information: 0 : pending work hc 32747756 added workItem hc 16973140
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.6824840Z
 System.Workflow.Runtime Information: 0 : pending work hc 63891231 added workItem hc 15165310
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.6834606Z
 System.Workflow.Runtime Information: 0 : 64f82660-15b8-4a7e-90b7-4e054164e923: Returning from ProtectedPersist: InstanceId 64f82660-15b8-4a7e-90b7-4e054164e923, hc: 61799993, ret=True
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.9354234Z
 System.Workflow.Runtime Information: 0 : WorkflowExecutor: unloaded workflow instance '64f82660-15b8-4a7e-90b7-4e054164e923'.  IsInstanceValid=False
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.9373766Z
 System.Workflow.Runtime.Hosting Information: 0 : Received OnIdle Event for instance, 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.9383532Z
  
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime:SchedulePersisted event raised for instance Id 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.9393298Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime:ScheduleUnloaded event raised for instance Id 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.9412830Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime::TryRemoveWorkflowExecutor, instance:64f82660-15b8-4a7e-90b7-4e054164e923, hc:61799993
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.9481192Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime::_removeInstance, instance:64f82660-15b8-4a7e-90b7-4e054164e923, hc:61799993
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.9481192Z

Workflow instance is removed from workflow runtime.

 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=00000000-0000-0000-0000-000000000000
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.9520256Z
 System.Workflow.Runtime Stop: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:28:48.9520256Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: CanRun is False
     ProcessId=5128
 DateTime=2012-06-27T00:28:48.9549554Z
  
  
 System.Workflow.Runtime.Hosting Information: 0 : Deserialized a Workflow1 [WorkflowProject11.Workflow1.Workflow1] to length 9045. Took 00:00:00.0859408.
     ProcessId=5128
 DateTime=2012-06-27T00:29:09.9645512Z

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:

 06/26/2012 16:05:52.69    
 w3wp.exe (0x27B4)    
 0x10E4    
 SharePoint Foundation    
 Workflow Infrastructure    
 0000   
 Verbose    
 Loaded instance data for instance: 64f82660-15b8-4a7e-90b7-4e054164e923, data size: 9045, processing id: 973d7273-526b-47a9-85f4-337f9fe82751

(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.

 System.Workflow.Runtime Information: 0 : Workflow Runtime: WorkflowExecutor: Loading instance 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9704108Z
 System.Workflow.Runtime Information: 0 : Adding context 1:Workflow1 for load
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9723640Z
 System.Workflow.Runtime Information: 0 : Adding context 2:onTaskChanged1 for load
     ProcessId=5128
 DateTime=2012-06-27T00:29:09.9723640Z

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

 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime:: replacing unusable executor for key 64f82660-15b8-4a7e-90b7-4e054164e923 with new one (hc: 28529661)
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9723640Z
 System.Workflow.Runtime.Hosting Information: 0 : TimerEventSubscriptionQueue: 64f82660-15b8-4a7e-90b7-4e054164e923 Resume
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9782236Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime:ScheduleLoaded event raised for instance Id 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9782236Z
 System.Workflow.Activities Information: 0 : Firing event OnTaskChanged for instance 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
 DateTime=2012-06-27T00:29:09.9801768Z

The event finally was raised to OnTaskChanged activity.

 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9801768Z
 System.Workflow.Runtime Start: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9801768Z
 System.Workflow.Runtime Information: 0 : Queuing Service: Enqueue item Queue ID -798539121 for Message Properties
 Interface Type:Microsoft.SharePoint.Workflow.ITaskService
 Method Name:OnTaskChanged
 CorrelationValues:
 b788bb83-2882-4587-b4a9-b8a3bfc7c1b9
  
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9801768Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((2)onTaskChanged1, System.Workflow.ComponentModel.QueueEventArgs)
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9811534Z
 System.Workflow.Runtime Information: 0 : Queuing Service: Notifying async subscriber on queue:'Message Properties
 Interface Type:Microsoft.SharePoint.Workflow.ITaskService
 Method Name:OnTaskChanged
 CorrelationValues:
 b788bb83-2882-4587-b4a9-b8a3bfc7c1b9
 ' activity:onTaskChanged1
     ProcessId=5128
 DateTime=2012-06-27T00:29:09.9811534Z

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

 System.Workflow.Runtime Information: 0 : pending work hc 43253384 added workItem hc 18075529
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: Schedule workflow 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=00000000-0000-0000-0000-000000000000
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime Stop: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: Running workflow 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: CanRun is True
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime.Hosting Information: 0 : ManualWorkflowSchedulerService: Executing 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime.Hosting Information: 0 : Running workflow 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime Transfer: 0 : , relatedActivityId=64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime Start: 0 : Workflow Trace
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((2)onTaskChanged1, System.Workflow.ComponentModel.QueueEventArgs)
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9821300Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: onTaskChanged1 Old:Executing; New:Closed
     ProcessId=5128
 DateTime=2012-06-27T00:29:09.9938492Z

onTaskChanged1 activity finished.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)whileActivity1, ActivityStatusChange('(2)onTaskChanged1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9938492Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((2)onTaskChanged1, System.Workflow.ComponentModel.QueueEventArgs)
     ProcessId=5128
     DateTime=2012-06-27T00:29:09.9938492Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)whileActivity1, ActivityStatusChange('(2)onTaskChanged1', Closed, Succeeded))
     ProcessId=5128
 DateTime=2012-06-27T00:29:09.9938492Z
  
 System.Workflow.Runtime Information: 0 : Removing context 2:onTaskChanged1
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0075216Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)whileActivity1, ActivityStatusChange('(1)whileActivity1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0075216Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)whileActivity1, ActivityStatusChange('(2)onTaskChanged1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0075216Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)whileActivity1, ActivityStatusChange('(1)whileActivity1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0075216Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: whileActivity1 Old:Executing; New:Closed

whileActivity1 activity finished.

 ProcessId=5128
     DateTime=2012-06-27T00:29:10.0143578Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)whileActivity1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0143578Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)whileActivity1, ActivityStatusChange('(1)whileActivity1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0153344Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)whileActivity1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0153344Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)sequenceActivity1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0153344Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)whileActivity1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0153344Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)sequenceActivity1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0153344Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: sequenceActivity1 Old:Executing; New:Closed

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

 ProcessId=5128
     DateTime=2012-06-27T00:29:10.0163110Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)sequenceActivity1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0163110Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)sequenceActivity1, ActivityStatusChange('(1)sequenceActivity1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0163110Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)sequenceActivity1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0163110Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: completeTask1 Old:Initialized; New:Executing
     ProcessId=5128
 DateTime=2012-06-27T00:29:10.0163110Z

Start executing completeTask1 activity.

 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: ActivityOperation((1)completeTask1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0163110Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)sequenceActivity1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0163110Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: ActivityOperation((1)completeTask1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0163110Z
 System.Workflow.Runtime Information: 0 : pending work hc 43253384 added workItem hc 59621546
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0387728Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: completeTask1 Old:Executing; New:Closed

Done executing completeTask1.

 ProcessId=5128
     DateTime=2012-06-27T00:29:10.0387728Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)completeTask1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0387728Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: ActivityOperation((1)completeTask1, Execute)
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0387728Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)completeTask1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0397494Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Scheduling entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)Workflow1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0407260Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)completeTask1', Closed, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0407260Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Running scheduled entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)Workflow1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0407260Z
 System.Workflow.Runtime Information: 0 : Activity Status Change - Activity: Workflow1 Old:Executing; New:Closed
     ProcessId=5128
 DateTime=2012-06-27T00:29:10.0407260Z

Done executing the entire workflow.

 System.Workflow.Runtime Information: 0 : CorrelationToken Uninitialized for workflowToken owner activity Workflow1
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0436558Z
 System.Workflow.Runtime Information: 0 : Queuing Service: Deleting Queue with ID -798539121 for Message Properties
 Interface Type:Microsoft.SharePoint.Workflow.ITaskService
 Method Name:OnTaskChanged
 CorrelationValues:
 b788bb83-2882-4587-b4a9-b8a3bfc7c1b9
  
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0475622Z
 System.Workflow.Runtime Information: 0 : pending work hc 43253384 added workItem hc 21353980
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0641644Z
 System.Workflow.Runtime Information: 0 : pending work hc 43253384 added workItem hc 33592719
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0641644Z
 System.Workflow.Activities Information: 0 : CorrelationTokenInvalidatedHandler subscription deleted SubId 8641f1db-ae5b-44df-b504-fe34946edcd0 QueueId Message Properties
 Interface Type:Microsoft.SharePoint.Workflow.ITaskService
 Method Name:OnTaskChanged
 CorrelationValues:
 b788bb83-2882-4587-b4a9-b8a3bfc7c1b9
  
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0641644Z
 System.Workflow.Runtime Information: 0 : CorrelationToken Uninitialized for taskToken owner activity Workflow1
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0661176Z
 System.Workflow.Runtime Information: 0 : Workflow Runtime: WorkflowExecutor: Calling SaveWorkflowInstanceState for instance 64f82660-15b8-4a7e-90b7-4e054164e923 hc 28529661
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0719772Z
 System.Workflow.Runtime Information: 0 : pending work hc 63891231 added workItem hc 8140213
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0719772Z
 System.Workflow.Runtime Information: 0 : Workflow Runtime: WorkflowExecutor: Calling CommitTransaction for instance 64f82660-15b8-4a7e-90b7-4e054164e923 hc 28529661
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0719772Z
 System.Workflow.Runtime Information: 0 : pending work hc 43253384 added workItem hc 18075529
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0719772Z
 System.Workflow.Runtime Information: 0 : pending work hc 43253384 added workItem hc 59621546
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0719772Z
 System.Workflow.Runtime Information: 0 : pending work hc 43253384 added workItem hc 21353980
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0729538Z
 System.Workflow.Runtime Information: 0 : pending work hc 43253384 added workItem hc 33592719
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0729538Z
 System.Workflow.Runtime Information: 0 : pending work hc 63891231 added workItem hc 8140213
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.0729538Z
 System.Workflow.Runtime Information: 0 : CorrelationToken Uninitialized for workflowToken owner activity Workflow1
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.1901458Z
 System.Workflow.Runtime Information: 0 : CorrelationToken Uninitialized for taskToken owner activity Workflow1
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.1901458Z
 System.Workflow.Runtime Information: 1 : Workflow Runtime: Scheduler: InstanceId: 64f82660-15b8-4a7e-90b7-4e054164e923 : Done with running scheduled entry: SubscriptionEvent((1)Workflow1, ActivityStatusChange('(1)Workflow1', Executing, Succeeded))
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.1901458Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime:SchedulePersisted event raised for instance Id 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.1901458Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime:ScheduleCompleted event raised for instance Id 64f82660-15b8-4a7e-90b7-4e054164e923
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.2018650Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime::TryRemoveWorkflowExecutor, instance:64f82660-15b8-4a7e-90b7-4e054164e923, hc:28529661
     ProcessId=5128
     DateTime=2012-06-27T00:29:10.2956186Z
 System.Workflow.Runtime.Hosting Information: 0 : WorkflowRuntime::_removeInstance, instance:64f82660-15b8-4a7e-90b7-4e054164e923, hc:28529661
     ProcessId=5128
 DateTime=2012-06-27T00:29:10.2956186Z

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.