这是本节的多页打印视图。 点击此处打印.

返回本页常规视图.

DurableTask quickstart

运行durabletask Core的Quickstart

1 - DurableTask quickstart

运行durabletask Core的Quickstart

以 DurableTask.Samples 为例

准备工作

azure storage

为了运行 sample，必须先准备好 azure storage，然后修改 samples\DurableTask.Samples\App.config 文件中的 StorageConnectionString:

  <appSettings>
    <add key="StorageConnectionString" value="DefaultEndpointsProtocol=https;AccountName=skyversioningdev;AccountKey=5dxW9E4xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;EndpointSuffix=core.windows.net" />
    <add key="taskHubName" value="SamplesHub" />
    <add key="SmtpNetworkCredentials" value="" />
  </appSettings>

dotnet 4.6.2 版本

打开 samples\DurableTask.Samples\DurableTask.Samples.csproj 可以看到对 .net 的要求是 .net 4.6.2

  <PropertyGroup>
    <AutoGenerateBindingRedirects>true</AutoGenerateBindingRedirects>
    <OutputType>Exe</OutputType>
    <TargetFramework>net462</TargetFramework>
  </PropertyGroup>

用 .net 8.0 可以正常运行，不用单独再安装 .net 4.6.2，但如果要 debug，则必须再单独安装 .net 4.6.2

TBD：要不要安装 .net 4.6.2 后面再验证一下。

运行 samples

构建

samples\DurableTask.Samples\

dotnet build

运行

以 Greetings sample 为例：

dotnet run -s Greetings

注意这个sample要求弹出一个窗口，因此不能在无界面的纯命令行下， 需要在 windows 界面下用 cmd 或者 bash 操作。否则会报错：

EventId : 4, Level : Warning, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : abdb59a4-a456-4b14-b1d6-c77a277f9199] [executionId : d23194
e7550c4f8da41d333911c80647] [sessionId : ] [message : Instance Id '[InstanceId: abdb59a4-a456-4b14-b1d6-c77a277f9199, ExecutionId: d23194e7550c4f8da41d333911c80647]' complet
ed in state Failed with result: Showing a modal dialog box or form when the application is not running in UserInteractive mode is not a valid operation. Specify the ServiceN
otification or DefaultDesktopOnly style to display a notification from a service application.] [exception : ] [eventType : TaskOrchestrationDispatcher-InstanceCompleted] , E
ventName : WarningInfo, Timestamp : 2024-04-28T01:39:38.0885765Z, ProcessId : 5716, ThreadId : 2952, ActivityId : d03ff6a5-eafb-4577-8b61-89cd486db722

"Reason": "Showing a modal dialog box or form when the application is not running in UserInteractive mode is not a valid operation. Specify the ServiceNotification or 
DefaultDesktopOnly style to display a notification from a service application.",

2 - quickstart原始日志

记录durabletask Quickstart的原始日志

命令开始执行：

$ dotnet run -c debug -s Greetings

Start Orchestration: Greetings

日志为：

 dotnet run -c debug -s Greetings
sleep 30 seconds
waiting for debugger to attach
done waiting for debugger to attach
Start Orchestration: Greetings
Workflow Instance Started: [InstanceId: 16af7b96-9409-4618-b33a-e7cc3a121a1a, ExecutionId: 410f7f47fdd9444ab3fb3ce6d00e9649]
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : WorkItemDispatcher('TaskOrchestrationDispatcher') starting. Id e0bc782c9aa84a0a8a256cf7a5d4e06e.] [info : ] [eventType : WorkItemDispatcherStart] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:56.3468829Z, ProcessId : 6536, ThreadId : 14068

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : WorkItemDispatcher('TaskActivityDispatcher') starting. Id 38b3e9add82043708a8643b81cf2f643.] [info : ] [eventType : WorkItemDispatcherStart] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:56.3625156Z, ProcessId : 6536, ThreadId : 14068

Waiting up to 60 seconds for completion.
EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting fetch with timeout of 00:00:30 (0/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:56.3625156Z, ProcessId : 6536, ThreadId : 12032

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting fetch with timeout of 00:00:30 (0/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:56.3625156Z, ProcessId : 6536, ThreadId : 9632

********* versioning  ************* LockNextTaskOrchestrationWorkItemAsync()
EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: After fetch (2961 ms) (0/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.3155825Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting fetch with timeout of 00:00:30 (1/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.3155825Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting to process workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.3155825Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing new event with Id -1 and type ExecutionStarted] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessEvent] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.3312077Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executing user orchestration: {
  "$type": "DurableTask.Core.OrchestrationRuntimeStateDump, DurableTask.Core",
  "Events": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    },
    {
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    }
  ],
  "NewEvents": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    },
    {
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    }
  ],
  "EventCount": 0,
  "NewEventsCount": 0
}] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.3312077Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executed user orchestration. Received 1 orchestrator actions: 0:ScheduleOrchestrator] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.3468324Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing orchestrator action of type ScheduleOrchestrator] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessOrchestratorAction] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.3468324Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

OnProcessWorkItemAsync - Processing orchestrator action of type ScheduleOrchestrator
EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: After fetch (3161 ms) (0/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.5187069Z, ProcessId : 6536, ThreadId : 13976, ActivityId : 1e0c99d8-4905-4149-a790-332669c907af

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting fetch with timeout of 00:00:30 (1/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.5187069Z, ProcessId : 6536, ThreadId : 13976, ActivityId : 1e0c99d8-4905-4149-a790-332669c907af

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting to process workItem 585e3de9-e953-4f39-af4f-c4a9b7bcd657] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.5187069Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

Waiting for user to enter name...
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Finished processing workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.8155822Z, ProcessId : 6536, ThreadId : 13976, ActivityId : 1e0c99d8-4905-4149-a790-332669c907af

User Name Entered: sky
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Finished processing workItem 585e3de9-e953-4f39-af4f-c4a9b7bcd657] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.3624392Z, ProcessId : 6536, ThreadId : 11248

********* versioning  ************* LockNextTaskOrchestrationWorkItemAsync()
EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: After fetch (5214 ms) (0/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 14068, ActivityId : f698e9a6-907c-4092-bd48-e19e7ba6a2a9

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting fetch with timeout of 00:00:30 (1/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 14068, ActivityId : f698e9a6-907c-4092-bd48-e19e7ba6a2a9

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting to process workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing new event with Id -1 and type TaskCompleted] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessEvent] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executing user orchestration: {
  "$type": "DurableTask.Core.OrchestrationRuntimeStateDump, DurableTask.Core",
  "Events": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    },
    {
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.GetUserTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 0,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 0,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.1905617Z"
    }
  ],
  "NewEvents": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 0,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.1905617Z"
    }
  ],
  "EventCount": 0,
  "NewEventsCount": 0
}] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executed user orchestration. Received 1 orchestrator actions: 1:ScheduleOrchestrator] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing orchestrator action of type ScheduleOrchestrator] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessOrchestratorAction] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

OnProcessWorkItemAsync - Processing orchestrator action of type ScheduleOrchestrator
EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: After fetch (5183 ms) (0/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.7061869Z, ProcessId : 6536, ThreadId : 11248, ActivityId : 413409db-6e47-413a-b78d-319a802d563c

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting fetch with timeout of 00:00:30 (1/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.7061869Z, ProcessId : 6536, ThreadId : 11248, ActivityId : 413409db-6e47-413a-b78d-319a802d563c

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting to process workItem d9bb55c6-f35e-495b-994e-b6bd106372b1] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.7061869Z, ProcessId : 6536, ThreadId : 9632, ActivityId : f698e9a6-907c-4092-bd48-e19e7ba6a2a9

Sending greetings to user: sky...
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Finished processing workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.9093117Z, ProcessId : 6536, ThreadId : 13976, ActivityId : f698e9a6-907c-4092-bd48-e19e7ba6a2a9

Greeting sent to sky
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Finished processing workItem d9bb55c6-f35e-495b-994e-b6bd106372b1] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:09.8780623Z, ProcessId : 6536, ThreadId : 10076, ActivityId : 1946c0da-30f0-4767-9aff-a5ff1e2bb884

********* versioning  ************* LockNextTaskOrchestrationWorkItemAsync()
EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: After fetch (5515 ms) (0/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting fetch with timeout of 00:00:30 (1/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting to process workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing new event with Id -1 and type TaskCompleted] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessEvent] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executing user orchestration: {
  "$type": "DurableTask.Core.OrchestrationRuntimeStateDump, DurableTask.Core",
  "Events": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    },
    {
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.GetUserTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 0,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 0,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:04.1905617Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.SendGreetingTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 1,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:09.7222239Z"
    }
  ],
  "NewEvents": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 1,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:09.7222239Z"
    }
  ],
  "EventCount": 0,
  "NewEventsCount": 0
}] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executed user orchestration. Received 1 orchestrator actions: 2:OrchestrationComplete] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing orchestrator action of type OrchestrationComplete] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessOrchestratorAction] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

OnProcessWorkItemAsync - Processing orchestrator action of type OrchestrationComplete
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Instance Id '[InstanceId: 16af7b96-9409-4618-b33a-e7cc3a121a1a, ExecutionId: 410f7f47fdd9444ab3fb3ce6d00e9649]' completed in state Completed with result: "Greeting sent to sky"] [info : ] [eventType : TaskOrchestrationDispatcher-InstanceCompleted] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : {{
  "$type": "DurableTask.Core.OrchestrationRuntimeStateDump, DurableTask.Core",
  "Events": [
    {{
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    }},
    {{
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.GetUserTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 0,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    }},
    {{
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    }},
    {{
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 0,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:04.1905617Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.SendGreetingTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    }},
    {{
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    }},
    {{
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 1,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:09.7222239Z"
    }},
    {{
      "$type": "DurableTask.Core.History.ExecutionCompletedEvent, DurableTask.Core",
      "EventType": 1,
      "OrchestrationStatus": 1,
      "Result": "[..snipped..]",
      "FailureDetails": null,
      "EventId": 2,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    }}
  ],
  "NewEvents": [
    {{
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 1,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:09.7222239Z"
    }},
    {{
      "$type": "DurableTask.Core.History.ExecutionCompletedEvent, DurableTask.Core",
      "EventType": 1,
      "OrchestrationStatus": 1,
      "Result": "[..snipped..]",
      "FailureDetails": null,
      "EventId": 2,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    }}
  ],
  "EventCount": 0,
  "NewEventsCount": 0
}}] [info : ] [eventType : TaskOrchestrationDispatcher-InstanceCompletionEvents] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [message : Deleting session state] [info : ] [eventType : TaskOrchestrationDispatcher-DeletingSessionState] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Finished processing workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.3624424Z, ProcessId : 6536, ThreadId : 13976, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

Task done: Completed
Press any key to quit.

3 - quickstart行为分析

分析durabletask Quickstart的行为

命令开始执行：

$ dotnet run -c debug -s Greetings

Start Orchestration: Greetings

start workflow instance

Workflow Instance 开始，生成 InstanceId 和 ExecutionId：

Workflow Instance Started: [InstanceId: 16af7b96-9409-4618-b33a-e7cc3a121a1a, ExecutionId: 410f7f47fdd9444ab3fb3ce6d00e9649]

然后产生了两个 Event （为什么 EventId 都是 3？）TaskOrchestrationDispatcher 和 TaskActivityDispatcher 启动，eventType 都是 WorkItemDispatcherStart：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : WorkItemDispatcher('TaskOrchestrationDispatcher') starting. Id e0bc782c9aa84a0a8a256cf7a5d4e06e.] [info : ] [eventType : WorkItemDispatcherStart] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:56.3468829Z, ProcessId : 6536, ThreadId : 14068

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : WorkItemDispatcher('TaskActivityDispatcher') starting. Id 38b3e9add82043708a8643b81cf2f643.] [info : ] [eventType : WorkItemDispatcherStart] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:56.3625156Z, ProcessId : 6536, ThreadId : 14068

超时时间为 60 秒：

Waiting up to 60 seconds for completion.

TaskOrchestrationDispatcher 和 TaskActivityDispatcher 开始 fetch：

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting fetch with timeout of 00:00:30 (0/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:56.3625156Z, ProcessId : 6536, ThreadId : 12032

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting fetch with timeout of 00:00:30 (0/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:56.3625156Z, ProcessId : 6536, ThreadId : 9632

这是我额外增加的日志，LockNextTaskOrchestrationWorkItemAsync 方法被调用了：

********* versioning  ************* LockNextTaskOrchestrationWorkItemAsync()

Orchestration第一轮

ExecutionStarted

TaskOrchestrationDispatcher 成功 fetch 到一个 workitem，然后又继续去 fetch 下一个：

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: After fetch (2961 ms) (0/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.3155825Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting fetch with timeout of 00:00:30 (1/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.3155825Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

TaskOrchestrationDispatcher 开始处理刚才 fetch 到的 workItem

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting to process workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.3155825Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

TaskOrchestrationDispatcher 开始处理 ExecutionStarted Event：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing new event with Id -1 and type ExecutionStarted] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessEvent] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.3312077Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

开始执行 user orchestration：

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executing user orchestration:

此时有两个 event ( OrchestratorStartedEvent 和 ExecutionStartedEvent), 这两个 event 都是 newEvent：

{
  "$type": "DurableTask.Core.OrchestrationRuntimeStateDump, DurableTask.Core",
  "Events": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    },
    {
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    }
  ],
  "NewEvents": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    },
    {
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    }
  ],
  "EventCount": 0,
  "NewEventsCount": 0
}

执行用户代码：GreetingsOrchestration

开始执行用户的编排代码，

 [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.3312077Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called

GreetingsOrchestration.RunTask called 是我增加的日志，这是 example 中的 Orchestration 的实现代码：

    public class GreetingsOrchestration : TaskOrchestration<string,string>
    {
        public override async Task<string> RunTask(OrchestrationContext context, string input)
        {
            Console.WriteLine("GreetingsOrchestration.RunTask called");
          
            string user = await context.ScheduleTask<string>(typeof(GetUserTask));
            string greeting = await context.ScheduleTask<string>(typeof(SendGreetingTask), user);
            return greeting;
        }
    }

Orchestration 执行完成，Executed user orchestration ，然后收到一个 orchestrator action ScheduleOrchestrator：

但这个有点质疑， task 还没完成了，可能是 await 退出了？？等下翻一下源码：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executed user orchestration. Received 1 orchestrator actions: 0:ScheduleOrchestrator] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.3468324Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

TaskOrchestrationDispatcher 开始处理 orchestrator action ScheduleOrchestrator：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing orchestrator action of type ScheduleOrchestrator] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessOrchestratorAction] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.3468324Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

OnProcessWorkItemAsync - Processing orchestrator action of type ScheduleOrchestrator

OnProcessWorkItemAsync - Processing orchestrator action of type ScheduleOrchestrator 是我增加的日志。

执行用户代码：GetUserTask

这个时候 TaskActivityDispatcher 终于 fetch 到一个 workitem 了：

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: After fetch (3161 ms) (0/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.5187069Z, ProcessId : 6536, ThreadId : 13976, ActivityId : 1e0c99d8-4905-4149-a790-332669c907af

TaskActivityDispatcher 继续 fetch 下一个：

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting fetch with timeout of 00:00:30 (1/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:50:59.5187069Z, ProcessId : 6536, ThreadId : 13976, ActivityId : 1e0c99d8-4905-4149-a790-332669c907af

TaskActivityDispatcher 开始处理刚才 fetch 到的 work item：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting to process workItem 585e3de9-e953-4f39-af4f-c4a9b7bcd657] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.5187069Z, ProcessId : 6536, ThreadId : 12032, ActivityId : d85171a0-5ef1-4e78-a32b-0d31cb396de7

这个 sample 里面就两个 task，第一个 task 是 GetUserTask：

            string user = await context.ScheduleTask<string>(typeof(GetUserTask));
            string greeting = await context.ScheduleTask<string>(typeof(SendGreetingTask), user);
            return greeting;

会弹出一个窗口要求输入用户的 name，日志如下：

Waiting for user to enter name...

输入名字 sky 之后，这个 task 执行完成，日志显示 Finished processing workItem， 这是 TaskOrchestrationDispatcher 打印的：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Finished processing workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:50:59.8155822Z, ProcessId : 6536, ThreadId : 13976, ActivityId : 1e0c99d8-4905-4149-a790-332669c907af

User Name Entered: sky

TaskActivityDispatcher 又打印了一次 Finished processing workItem 的日志：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Finished processing workItem 585e3de9-e953-4f39-af4f-c4a9b7bcd657] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.3624392Z, ProcessId : 6536, ThreadId : 11248

TaskOrchestrationDispatcher 又一次 fetch 到 workitem：

********* versioning  ************* LockNextTaskOrchestrationWorkItemAsync()
EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: After fetch (5214 ms) (0/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 14068, ActivityId : f698e9a6-907c-4092-bd48-e19e7ba6a2a9

TaskOrchestrationDispatcher 继续 fetch 下一个 workitem ：

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting fetch with timeout of 00:00:30 (1/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 14068, ActivityId : f698e9a6-907c-4092-bd48-e19e7ba6a2a9

TaskOrchestrationDispatcher 开始处理刚才 fetch 到的 workitem：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting to process workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

原来是 TaskCompleted Event：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing new event with Id -1 and type TaskCompleted] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessEvent] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executing user orchestration:

user orchestration 除了之前的两个 event（OrchestratorStartedEvent 和 ExecutionStartedEvent）之外，还多了 TaskScheduledEvent（GetUserTask），OrchestratorCompletedEvent ， OrchestratorStartedEvent， TaskCompletedEvent。

{
  "$type": "DurableTask.Core.OrchestrationRuntimeStateDump, DurableTask.Core",
  "Events": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    },
    {
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.GetUserTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 0,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 0,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.1905617Z"
    }
  ],
  "NewEvents": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 0,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.1905617Z"
    }
  ],
  "EventCount": 0,
  "NewEventsCount": 0
}

其中有一个 OrchestratorStartedEvent 是新的，还有 TaskCompletedEvent。

Orchestration第二轮

TaskOrchestrationDispatcher 再次 Execute User Orchestration, 这里我增加了日志打印，把 ProcessEvent 的 evnet 都打印了出来：

[info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted

Executed user orchestration 执行完之后，又收到了一个 orchestrator action ScheduleOrchestrator：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executed user orchestration. Received 1 orchestrator actions: 1:ScheduleOrchestrator] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

TaskOrchestrationDispatcher 开始执行 ScheduleOrchestrator 这个 orchestrator action：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing orchestrator action of type ScheduleOrchestrator] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessOrchestratorAction] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.5343127Z, ProcessId : 6536, ThreadId : 9632, ActivityId : fec9f5fa-cfa6-4115-95f1-7f40e3e9d6aa

OnProcessWorkItemAsync - Processing orchestrator action of type ScheduleOrchestrator

执行用户代码：SendGreetingTask

TaskActivityDispatcher 又一次 fetch 到 workitem：

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: After fetch (5183 ms) (0/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.7061869Z, ProcessId : 6536, ThreadId : 11248, ActivityId : 413409db-6e47-413a-b78d-319a802d563c

TaskActivityDispatcher 继续 fetch 下一个

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting fetch with timeout of 00:00:30 (1/10 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:04.7061869Z, ProcessId : 6536, ThreadId : 11248, ActivityId : 413409db-6e47-413a-b78d-319a802d563c

TaskActivityDispatcher 开始处理刚才 fetch 到的 work item

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Starting to process workItem d9bb55c6-f35e-495b-994e-b6bd106372b1] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.7061869Z, ProcessId : 6536, ThreadId : 9632, ActivityId : f698e9a6-907c-4092-bd48-e19e7ba6a2a9

也就是执行第二个task，SendGreetingTask，表现为打印如下日志：

Sending greetings to user: sky...
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Finished processing workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:04.9093117Z, ProcessId : 6536, ThreadId : 13976, ActivityId : f698e9a6-907c-4092-bd48-e19e7ba6a2a9

Greeting sent to sky

在两个日志打印 Sending greetings to user: sky... 和 Sending greetings to user: sky... 之间，有一个 Thread.Sleep(5 * 1000); :

public sealed class SendGreetingTask : TaskActivity<string, string>
    {
        protected override string Execute(DurableTask.Core.TaskContext context, string user)
        {
            string message;
            if (!string.IsNullOrWhiteSpace(user) && user.Equals("TimedOut"))
            {
                message = "GetUser Timed out!!!";
                Console.WriteLine(message);
            }
            else
            {
                Console.WriteLine("Sending greetings to user: " + user + "...");

                Thread.Sleep(5 * 1000);

                message = "Greeting sent to " + user;
                Console.WriteLine(message);
            }

            return message;
        }
    }

TBD: 这个 sleep 有问题，按说不能直接这样 sleep 的。

TaskActivityDispatcher 完成第二个 work item （SendGreetingTask） 的处理

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskActivityDispatcher-38b3e9add82043708a8643b81cf2f643-0: Finished processing workItem d9bb55c6-f35e-495b-994e-b6bd106372b1] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:09.8780623Z, ProcessId : 6536, ThreadId : 10076, ActivityId : 1946c0da-30f0-4767-9aff-a5ff1e2bb884

TaskOrchestrationDispatcher 继续 fetch 到下一个 work item

********* versioning  ************* LockNextTaskOrchestrationWorkItemAsync()
EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: After fetch (5515 ms) (0/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-EndFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

TaskOrchestrationDispatcher 继续 fetch 下一个 work item:

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting fetch with timeout of 00:00:30 (1/100 max)] [info : ] [eventType : WorkItemDispatcherDispatch-StartFetch] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

TaskOrchestrationDispatcher 开始处理 fetch 到的 work item：

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Starting to process workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-Begin] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

TaskOrchestrationDispatcher 处理 TaskCompleted event

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing new event with Id -1 and type TaskCompleted] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessEvent] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

Orchestration第三轮

EventId : 1, Level : Verbose, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executing user orchestration: 

{
  "$type": "DurableTask.Core.OrchestrationRuntimeStateDump, DurableTask.Core",
  "Events": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    },
    {
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.GetUserTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 0,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 0,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:04.1905617Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.SendGreetingTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    },
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 1,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:09.7222239Z"
    }
  ],
  "NewEvents": [
    {
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    },
    {
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 1,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:09.7222239Z"
    }
  ],
  "EventCount": 0,
  "NewEventsCount": 0
}

 [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin] , EventName : TraceInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Executed user orchestration. Received 1 orchestrator actions: 2:OrchestrationComplete] [info : ] [eventType : TaskOrchestrationDispatcher-ExecuteUserOrchestration-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Processing orchestrator action of type OrchestrationComplete] [info : ] [eventType : TaskOrchestrationDispatcher-ProcessOrchestratorAction] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

OnProcessWorkItemAsync - Processing orchestrator action of type OrchestrationComplete
EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : Instance Id '[InstanceId: 16af7b96-9409-4618-b33a-e7cc3a121a1a, ExecutionId: 410f7f47fdd9444ab3fb3ce6d00e9649]' completed in state Completed with result: "Greeting sent to sky"] [info : ] [eventType : TaskOrchestrationDispatcher-InstanceCompleted] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [executionId : 410f7f47fdd9444ab3fb3ce6d00e9649] [sessionId : ] [message : {{
  "$type": "DurableTask.Core.OrchestrationRuntimeStateDump, DurableTask.Core",
  "Events": [
    {{
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:50:59.3312077Z"
    }},
    {{
      "$type": "DurableTask.Core.History.ExecutionStartedEvent, DurableTask.Core",
      "OrchestrationInstance": null,
      "EventType": 0,
      "ParentInstance": null,
      "Name": null,
      "Version": null,
      "Input": "[..snipped..]",
      "Tags": null,
      "Correlation": null,
      "ParentTraceContext": null,
      "ScheduledStartTime": null,
      "Generation": null,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:54.3937812Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.GetUserTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 0,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    }},
    {{
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:50:59.3468324Z"
    }},
    {{
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 0,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:04.1905617Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskScheduledEvent, DurableTask.Core",
      "EventType": 4,
      "Name": "DurableTask.Samples.Greetings.SendGreetingTask",
      "Version": "",
      "Input": "[..snipped..]",
      "ParentTraceContext": null,
      "EventId": 1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    }},
    {{
      "$type": "DurableTask.Core.History.OrchestratorCompletedEvent, DurableTask.Core",
      "EventType": 13,
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:04.5343127Z"
    }},
    {{
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 1,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:09.7222239Z"
    }},
    {{
      "$type": "DurableTask.Core.History.ExecutionCompletedEvent, DurableTask.Core",
      "EventType": 1,
      "OrchestrationStatus": 1,
      "Result": "[..snipped..]",
      "FailureDetails": null,
      "EventId": 2,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    }}
  ],
  "NewEvents": [
    {{
      "$type": "DurableTask.Core.History.OrchestratorStartedEvent, DurableTask.Core",
      "EventType": 12,
      "EventId": -1,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    }},
    {{
      "$type": "DurableTask.Core.History.TaskCompletedEvent, DurableTask.Core",
      "EventType": 5,
      "TaskScheduledId": 1,
      "Result": "[..snipped..]",
      "EventId": -1,
      "IsPlayed": true,
      "Timestamp": "2024-04-28T01:51:09.7222239Z"
    }},
    {{
      "$type": "DurableTask.Core.History.ExecutionCompletedEvent, DurableTask.Core",
      "EventType": 1,
      "OrchestrationStatus": 1,
      "Result": "[..snipped..]",
      "FailureDetails": null,
      "EventId": 2,
      "IsPlayed": false,
      "Timestamp": "2024-04-28T01:51:10.0499421Z"
    }}
  ],
  "EventCount": 0,
  "NewEventsCount": 0
}}] [info : ] [eventType : TaskOrchestrationDispatcher-InstanceCompletionEvents] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : 16af7b96-9409-4618-b33a-e7cc3a121a1a] [message : Deleting session state] [info : ] [eventType : TaskOrchestrationDispatcher-DeletingSessionState] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.0499421Z, ProcessId : 6536, ThreadId : 12032, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

EventId : 3, Level : Informational, Message : , Payload : [source : DurableTask.Core-durabletask.samples] [instanceId : ] [executionId : ] [sessionId : ] [message : TaskOrchestrationDispatcher-e0bc782c9aa84a0a8a256cf7a5d4e06e-0: Finished processing workItem 16af7b96-9409-4618-b33a-e7cc3a121a1a] [info : ] [eventType : WorkItemDispatcherProcess-End] , EventName : InfoInfo, Timestamp : 2024-04-28T01:51:10.3624424Z, ProcessId : 6536, ThreadId : 13976, ActivityId : 4d43f051-56be-45ca-912c-7043390e8cd3

Task done: Completed
Press any key to quit.

4 - quickstart事件顺序

分析durabletask Quickstart中事件出现和处理的顺序
Orchestration
Fetch		 Activity
Fetch		 执行用户代码
Start Start
第一轮
StartFetch StartFetch
—-» ExecutionStarted
EndFetch
StartFetch
GreetingsOrchestration
–>. ??
EndFetch
StartFetch
GetUserTask
第二轮
—-» TaskCompleted
EndFetch
StartFetch
SendGreetingTask
第三轮
EndFetch

LockNextTaskOrchestrationWorkItemAsync

LockNextTaskOrchestrationWorkItemAsync 方法被调用的这个日志出现过三次：

********* versioning  ************* LockNextTaskOrchestrationWorkItemAsync()

第一次被调用时，event history 列表有：

  • OrchestratorStartedEvent (new)
  • ExecutionStartedEvent (new)

对应日志：

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called

第二次被调用时，event history 列表有：

  • OrchestratorStartedEvent
  • ExecutionStartedEvent
  • TaskScheduledEvent
  • OrchestratorCompletedEvent
  • OrchestratorStartedEvent (new)
  • TaskCompletedEvent (new)

对应日志：

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted

第三次被调用时，event history 列表有：

  • OrchestratorStartedEvent
  • ExecutionStartedEvent
  • TaskScheduledEvent
  • OrchestratorCompletedEvent
  • OrchestratorStartedEvent
  • TaskCompletedEvent
  • TaskScheduledEvent
  • OrchestratorCompletedEvent
  • OrchestratorStartedEvent (new)
  • TaskCompletedEvent (new)

对应日志：

ProcessEvent: EventType=ExecutionStarted
GreetingsOrchestration.RunTask called
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted
ProcessEvent: EventType=TaskScheduled
ProcessEvent: EventType=OrchestratorCompleted
ProcessEvent: EventType=TaskCompleted