Strange behavior for a workflow

Question

Hi!

I have a lot of strage behavior regarding my workflow host and it's workflows. I'll jump right into it. I use both the persistance and tracking service that comes out of the box. The WF host is hosted as a windows service and I have a WCF interface to "talk" to the host. WCF exposes methods like: "Start this workflow", "Change the status of this workflow" and "Terminate this workflow".

The strange behavior I talk about is this. When I call "Terminate workflow" I look in the tracking table WorkflowInstanceEvent I see this for the particular workflow:

WorkflowInstanceEventId WorkflowInstanceInternalId TrackingWorkflowEventId EventDateTime EventOrder EventArgTypeId EventArg DbEventDateTime
124715 15769 0 2010-09-27 17:20:42.210 1 NULL NULL 2010-09-27 17:20:45.930
124717 15769 12 2010-09-27 17:20:42.213 2 NULL NULL 2010-09-27 17:20:45.937
124719 15769 2 2010-09-27 17:20:42.237 5 NULL NULL 2010-09-27 17:20:45.957
124720 15769 6 2010-09-27 17:20:42.240 6 NULL NULL 2010-09-27 17:20:45.960
124721 15769 5 2010-09-27 17:20:42.247 7 NULL NULL 2010-09-27 17:20:45.967
124802 15769 7 2010-09-27 17:20:49.723 8 NULL NULL 2010-09-27 17:20:53.450
125143 15769 7 2010-09-28 07:41:26.707 8 NULL NULL 2010-09-28 07:41:28.243
125336 15769 7 2010-09-28 08:41:30.713 8 NULL NULL 2010-09-28 08:41:33.207
125418 15769 9 2010-09-28 10:02:10.083 9 4 0x0001000000FFFFFFFF01000000000000000C020000005A53797374656D2E576F726B666C6F772E52756E74696D652C2056657273696F6E3D332E302E302E302C2043756C747572653D6E65757472616C2C205075626C69634B6579546F6B656E3D333162663338353661643336346533350C030000006153797374656D2E576F726B666C6F772E436F6D706F6E656E744D6F64656C2C2056657273696F6E3D332E302E302E302C2043756C747572653D6E65757472616C2C205075626C69634B6579546F6B656E3D3331626633383536616433363465333505010000004453797374656D2E576F726B666C6F772E52756E74696D652E547261636B696E672E547261636B696E67576F726B666C6F775465726D696E617465644576656E744172677301000000025F65043A53797374656D2E576F726B666C6F772E436F6D706F6E656E744D6F64656C2E576F726B666C6F775465726D696E61746564457863657074696F6E0300000002000000090400000005040000003A53797374656D2E576F726B666C6F772E436F6D706F6E656E744D6F64656C2E576F726B666C6F775465726D696E61746564457863657074696F6E0B00000009436C6173734E616D65074D65737361676504446174610E496E6E6572457863657074696F6E0748656C7055524C10537461636B5472616365537472696E671652656D6F7465537461636B5472616365537472696E671052656D6F7465537461636B496E6465780F457863657074696F6E4D6574686F640748526573756C7406536F7572636501010303010101000100011E53797374656D2E436F6C6C656374696F6E732E4944696374696F6E6172791053797374656D2E457863657074696F6E08080300000006050000003A53797374656D2E576F726B666C6F772E436F6D706F6E656E744D6F64656C2E576F726B666C6F775465726D696E61746564457863657074696F6E06060000002341626F727465642062792054524146494B5645524B45545C7376637A747061646D696E0A0A0A0A0A000000000A001513800A0B 2010-09-28 10:02:12.677
125419 15769 5 2010-09-28 10:02:10.103 10 NULL NULL 2010-09-28 10:02:12.693
125420 15769 10 2010-09-28 10:02:10.113 11 NULL NULL 2010-09-28 10:02:12.703
125421 15769 7 2010-09-28 10:02:14.250 8 NULL NULL 2010-09-28 10:02:16.837

The interesting part is column 3. Look how the status goes from 9 (Terminated) to 5 (Persisted), 10 (Aborted) and finally 7 (Loaded).

 

In my world a terminated workflow is the final status for a workflow. How is it possible for the workflow to continue to live?

 

 

Answer 1

What is the value of the IsTransactional property on your SqlTrackingService?

If it is "false", what you see here can happen. When IsTransactional is false, the tracking events are written out to the tracking database "as they happen", rather than being batched up and participating in the same transaction that is used for writes to the persistence database.

Note the "Aborted" event after the "Terminated" and "Persisted" events. This indicates that the attempt to persist the workflow instance state of Terminated failed. So the previous instance state remains in the persistence database. That is why the last "Loaded" event indicates a EventOrder value of 8, which preceeds the event order ids for the Terminated and Persisted events (9 and 10). Because the persist failed, the instance state in the persistence database is from the last successful persist. The event order id is persisted as part of the workflow instance state.

If IsTransactional is "true", then the tracking service "batches up" the tracking events until the workflow persists and those events are written under the same transaction that is used to write to the persistence database. In that case, if the final "Persist" had failed, you would not see the "Terminated", "Persisted", and "Aborted" events (event order 9, 10, and 11) in the tracking database because their write would have been backed out because the persistence transaction failed.

Thanks for your question. I hope this answers it.

Jim

 

Answer 2

Hi Jim!

You are right about IsTransactional, it is set to false. This explains the behavior, but now I need to investigate why the instance state couldn't be persisted. Beside SQL connectivity, do you have any ideas?

Answer 3

You might get the information you need by turning on tracing.

See http://support.microsoft.com/kb/972914/en-us for more information.

To reduce the amount of output, you should consider setting the trace level to Warning by adding

      <add name="TraceLevelSwitch" value="2" />

as follows:

<configuration>
  <system.diagnostics>
    <switches>
      <add name="traceLevel" value="Warning" />
    </switches>
  </system.diagnostics>
</configuration>