Azure-functions-durable-extension: Durable Entity keys do not support certain characters.

Created on 22 Nov 2020  路  9Comments  路  Source: Azure/azure-functions-durable-extension

Description

Given a Durable Orchestrator which operates on a Durable Entity with a very long key behaves very differently from one with a short key. The main difference is that the orchestrator takes too much time to complete when it operates on an entity with a long key. Sometimes it can happen that it never completes.

The docs do not mention any constraints about the entity ID. Therefore I assume that the code below is correct and that the huge discrepancy between the runtime of orchestrators operating on an entity with short key and the runtime of orchestrators operating on an entity with long key is a bug.

Some of the observations in the logs below might be intentional.

Actual behavior

The logs below are written to the console in the case when the orchestrator RestartOrchestrator operates on the entity RestartCounter with a very long key. The places in the log which differ from expected behaviour are annotated.

[2020-11-21T20:37:11.127Z] Executing HTTP request: {
[2020-11-21T20:37:11.130Z]   requestId: "f60f4466-f317-4a34-942f-f1334574c67c",
[2020-11-21T20:37:11.131Z]   method: "POST",
[2020-11-21T20:37:11.133Z]   userAgent: "PostmanRuntime/7.26.8",
[2020-11-21T20:37:11.134Z]   uri: "/api/Alert"
[2020-11-21T20:37:11.135Z] }
[2020-11-21T20:37:11.252Z] Executing 'Alert' (Reason='This function was programmatically called via the host APIs.', Id=06002ef7-4f99-4e12-8e44-9c811027e511)
[2020-11-21T20:37:11.282Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' scheduled. Reason: NewInstance. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 2.
[2020-11-21T20:37:11.467Z] Executed 'Alert' (Succeeded, Id=06002ef7-4f99-4e12-8e44-9c811027e511, Duration=264ms)
[2020-11-21T20:37:11.543Z] Executed HTTP request: {
[2020-11-21T20:37:11.547Z]   requestId: "f60f4466-f317-4a34-942f-f1334574c67c",
[2020-11-21T20:37:11.550Z]   identities: "",
[2020-11-21T20:37:11.552Z]   status: "200",
[2020-11-21T20:37:11.553Z]   duration: "413"
[2020-11-21T20:37:11.554Z] }
[2020-11-21T20:37:11.650Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=54dd20ce-6779-4a74-8e55-c31b97dc434d)
[2020-11-21T20:37:11.660Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' started. IsReplay: False. Input: (520 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 3. TaskEventId: -1
[2020-11-21T20:37:11.714Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:566436c5-f69d-5c28-b745-500f81f8a481. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 4.
[2020-11-21T20:37:11.721Z] 51308c0e2b554aca99130cd0f196b852: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 5.
[2020-11-21T20:37:11.730Z] Executed 'RestartOrchestrator' (Succeeded, Id=54dd20ce-6779-4a74-8e55-c31b97dc434d, Duration=81ms)
[2020-11-21T20:37:11.733Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 6.
[2020-11-21T20:37:11.943Z] Executing 'RestartCounter' (Reason='(null)', Id=ca2efc7f-bbd9-45b8-b763-a5e0b5339e67)
[2020-11-21T20:37:11.964Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 566436c5-f69d-5c28-b745-500f81f8a481 in 8.3835ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 7.
[2020-11-21T20:37:11.994Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 8. TaskEventId: -1
[2020-11-21T20:37:12.011Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 9. TaskEventId: -1
[2020-11-21T20:37:12.042Z] Executed 'RestartCounter' (Succeeded, Id=ca2efc7f-bbd9-45b8-b763-a5e0b5339e67, Duration=100ms)
[2020-11-21T20:37:12.060Z] Executing 'RestartCounter' (Reason='(null)', Id=8aae6045-0552-48b7-92a3-9d1b5cbd8180)
[2020-11-21T20:37:12.074Z] Executed 'RestartCounter' (Succeeded, Id=8aae6045-0552-48b7-92a3-9d1b5cbd8180, Duration=14ms)
[2020-11-21T20:37:12.267Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=6404f002-c870-4637-81cf-446243e2e4fe)
[2020-11-21T20:37:12.274Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: 566436c5-f69d-5c28-b745-500f81f8a481. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 10.
[2020-11-21T20:37:12.287Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:929888b1-98f6-512e-8136-87559e837e0b. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 11.
[2020-11-21T20:37:12.307Z] 51308c0e2b554aca99130cd0f196b852: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 12.
[2020-11-21T20:37:12.334Z] Executed 'RestartOrchestrator' (Succeeded, Id=6404f002-c870-4637-81cf-446243e2e4fe, Duration=66ms)
[2020-11-21T20:37:12.356Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 13.
[2020-11-21T20:37:22.306Z] Executing 'RestartCounter' (Reason='(null)', Id=ed6d2937-31ff-48d0-88ae-b19b3f1934fb)
[2020-11-21T20:37:22.314Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 566436c5-f69d-5c28-b745-500f81f8a481 in 2.5269ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 14.
[2020-11-21T20:37:22.319Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation 929888b1-98f6-512e-8136-87559e837e0b in 2.1144ms. IsReplay: False. Input: (null). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 15.

Observation: The previous operation GetCount 566436c5-f69d-5c28-b745-500f81f8a481 is repeated. This is not the case when a short key is used.

```[2020-11-21T20:37:22.331Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 16. TaskEventId: -1
[2020-11-21T20:37:22.347Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 17. TaskEventId: -1
[2020-11-21T20:37:22.351Z] Executed 'RestartCounter' (Succeeded, Id=ed6d2937-31ff-48d0-88ae-b19b3f1934fb, Duration=46ms)
[2020-11-21T20:37:22.360Z] Executing 'RestartCounter' (Reason='(null)', Id=e56743dc-689a-4853-a787-a032c9531d7b)
[2020-11-21T20:37:22.363Z] Executed 'RestartCounter' (Succeeded, Id=e56743dc-689a-4853-a787-a032c9531d7b, Duration=2ms)
[2020-11-21T20:37:32.294Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=01bbc57b-9daf-42b6-8b7d-c7513aca04eb)
[2020-11-21T20:37:32.301Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '566436c5-f69d-5c28-b745-500f81f8a481' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 18.


Observation: Orchestrator writes the previous operation event to the queue before receiving the response from entity. This is not the case when a short key is used.

[2020-11-21T20:37:32.304Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: 929888b1-98f6-512e-8136-87559e837e0b. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 19.
[2020-11-21T20:37:32.308Z] Count is 0.
[2020-11-21T20:37:32.321Z] Date is 00:00:00.
[2020-11-21T20:37:32.340Z] Resetting entity.
[2020-11-21T20:37:32.350Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:4467171e-91b0-5033-924e-17e162a6264e. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 20.
[2020-11-21T20:37:32.379Z] 51308c0e2b554aca99130cd0f196b852: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 21.
[2020-11-21T20:37:32.384Z] Executed 'RestartOrchestrator' (Succeeded, Id=01bbc57b-9daf-42b6-8b7d-c7513aca04eb, Duration=90ms)
[2020-11-21T20:37:32.409Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 22.
[2020-11-21T20:37:42.299Z] Executing 'RestartCounter' (Reason='(null)', Id=59056806-c0b7-49b4-8acd-53c3924c24b7)
[2020-11-21T20:37:42.323Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 566436c5-f69d-5c28-b745-500f81f8a481 in 5.4701ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 23.
[2020-11-21T20:37:42.364Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation 929888b1-98f6-512e-8136-87559e837e0b in 1.1631ms. IsReplay: False. Input: (null). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 24.
[2020-11-21T20:37:42.375Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'Reset' operation 4467171e-91b0-5033-924e-17e162a6264e in 1.0106ms. IsReplay: False. Input: (null). Output: (null). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 25.


Observation: The previous operations GetCount 566436c5-f69d-5c28-b745-500f81f8a481 and GetDate 929888b1-98f6-512e-8136-87559e837e0b are repeated. This is not the case when a short key is used.

[2020-11-21T20:37:42.397Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 26. TaskEventId: -1
[2020-11-21T20:37:42.418Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 27. TaskEventId: -1
[2020-11-21T20:37:42.445Z] Executed 'RestartCounter' (Succeeded, Id=59056806-c0b7-49b4-8acd-53c3924c24b7, Duration=146ms)
[2020-11-21T20:37:42.465Z] Executing 'RestartCounter' (Reason='(null)', Id=19fc8897-3925-4465-8de4-e8687abe620c)
[2020-11-21T20:37:42.485Z] Executed 'RestartCounter' (Succeeded, Id=19fc8897-3925-4465-8de4-e8687abe620c, Duration=20ms)
[2020-11-21T20:37:52.311Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=71c7ea07-ebf3-4f11-b500-5871fe1a2dba)
[2020-11-21T20:37:52.318Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '566436c5-f69d-5c28-b745-500f81f8a481' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 28.
[2020-11-21T20:37:52.320Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '929888b1-98f6-512e-8136-87559e837e0b' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 29.


Observation: Orchestrator writes the previous operation events to the queue before receiving the response from entity. This is not the case when a short key is used.

[2020-11-21T20:37:52.323Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: 4467171e-91b0-5033-924e-17e162a6264e. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 30.
[2020-11-21T20:37:52.341Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:225a693c-7ea4-533c-a580-8fe0020bd6d3. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 31.
[2020-11-21T20:37:52.346Z] 51308c0e2b554aca99130cd0f196b852: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 32.
[2020-11-21T20:37:52.350Z] Executed 'RestartOrchestrator' (Succeeded, Id=71c7ea07-ebf3-4f11-b500-5871fe1a2dba, Duration=38ms)
[2020-11-21T20:37:52.352Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 33.
[2020-11-21T20:38:02.320Z] Executing 'RestartCounter' (Reason='(null)', Id=f5c4b874-9067-4cf3-b0f0-3211d4c3840d)
[2020-11-21T20:38:02.325Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 566436c5-f69d-5c28-b745-500f81f8a481 in 1.6235ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 34.
[2020-11-21T20:38:02.329Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation 929888b1-98f6-512e-8136-87559e837e0b in 0.3925ms. IsReplay: False. Input: (null). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 35.
[2020-11-21T20:38:02.332Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'Reset' operation 4467171e-91b0-5033-924e-17e162a6264e in 0.3202ms. IsReplay: False. Input: (null). Output: (null). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 36.
[2020-11-21T20:38:02.345Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 225a693c-7ea4-533c-a580-8fe0020bd6d3 in 0.6868ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 37.


Observation: The previous operations GetCount 566436c5-f69d-5c28-b745-500f81f8a481, GetDate 929888b1-98f6-512e-8136-87559e837e0b, and Reset 4467171e-91b0-5033-924e-17e162a6264e are repeated. This is not the case when a short key is used.

[2020-11-21T20:38:02.359Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 38. TaskEventId: -1
[2020-11-21T20:38:02.363Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 39. TaskEventId: -1
[2020-11-21T20:38:02.366Z] Executed 'RestartCounter' (Succeeded, Id=f5c4b874-9067-4cf3-b0f0-3211d4c3840d, Duration=45ms)
[2020-11-21T20:38:02.379Z] Executing 'RestartCounter' (Reason='(null)', Id=f083b93c-6a65-4942-b96a-e71cb16e9d62)
[2020-11-21T20:38:02.381Z] Executed 'RestartCounter' (Succeeded, Id=f083b93c-6a65-4942-b96a-e71cb16e9d62, Duration=2ms)
[2020-11-21T20:38:12.331Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=f7a75eec-7544-49f4-8a50-9fc167d2c6f4)
[2020-11-21T20:38:12.338Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '566436c5-f69d-5c28-b745-500f81f8a481' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 40.
[2020-11-21T20:38:12.340Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '929888b1-98f6-512e-8136-87559e837e0b' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 41.
[2020-11-21T20:38:12.342Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '4467171e-91b0-5033-924e-17e162a6264e' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 42.


Observation: Orchestrator writes the previous operation events to the queue before receiving the response from entity. This is not the case when a short key is used.

[2020-11-21T20:38:12.344Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: 225a693c-7ea4-533c-a580-8fe0020bd6d3. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 43.
[2020-11-21T20:38:12.347Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:d9a3ffab-f6e4-5651-8791-2fa5c59d6da5. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 44.
[2020-11-21T20:38:12.350Z] 51308c0e2b554aca99130cd0f196b852: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 45.
[2020-11-21T20:38:12.353Z] Executed 'RestartOrchestrator' (Succeeded, Id=f7a75eec-7544-49f4-8a50-9fc167d2c6f4, Duration=21ms)
[2020-11-21T20:38:12.365Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 46.
[2020-11-21T20:38:22.333Z] Executing 'RestartCounter' (Reason='(null)', Id=db5c8fff-9aaf-4089-bf0e-540149602023)
[2020-11-21T20:38:22.340Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 566436c5-f69d-5c28-b745-500f81f8a481 in 1.7539ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 47.
[2020-11-21T20:38:22.364Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation 929888b1-98f6-512e-8136-87559e837e0b in 0.592ms. IsReplay: False. Input: (null). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 48.
[2020-11-21T20:38:22.387Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'Reset' operation 4467171e-91b0-5033-924e-17e162a6264e in 0.4209ms. IsReplay: False. Input: (null). Output: (null). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 49.
[2020-11-21T20:38:22.428Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 225a693c-7ea4-533c-a580-8fe0020bd6d3 in 0.9721ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 50.
[2020-11-21T20:38:22.437Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation d9a3ffab-f6e4-5651-8791-2fa5c59d6da5 in 0.7694ms. IsReplay: False. Input: (null). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 51.


Observation: The previous operations GetCount 566436c5-f69d-5c28-b745-500f81f8a481, GetDate 929888b1-98f6-512e-8136-87559e837e0b, Reset 4467171e-91b0-5033-924e-17e162a6264e, and GetCount 225a693c-7ea4-533c-a580-8fe0020bd6d3 are repeated. This is not the case when a short key is used.

[2020-11-21T20:38:22.479Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 52. TaskEventId: -1
[2020-11-21T20:38:22.527Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 53. TaskEventId: -1
[2020-11-21T20:38:22.577Z] Executed 'RestartCounter' (Succeeded, Id=db5c8fff-9aaf-4089-bf0e-540149602023, Duration=243ms)
[2020-11-21T20:38:22.604Z] Executing 'RestartCounter' (Reason='(null)', Id=7b18c57c-82ee-4f20-8aef-e276b6e513c4)
[2020-11-21T20:38:22.622Z] Executed 'RestartCounter' (Succeeded, Id=7b18c57c-82ee-4f20-8aef-e276b6e513c4, Duration=17ms)
[2020-11-21T20:38:32.342Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=d8091903-3687-42bb-b6a1-48200fb9772c)
[2020-11-21T20:38:32.356Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '566436c5-f69d-5c28-b745-500f81f8a481' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 54.
[2020-11-21T20:38:32.378Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '929888b1-98f6-512e-8136-87559e837e0b' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 55.
[2020-11-21T20:38:32.395Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '4467171e-91b0-5033-924e-17e162a6264e' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 56.
[2020-11-21T20:38:32.399Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '225a693c-7ea4-533c-a580-8fe0020bd6d3' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 57.


Observation: Orchestrator writes the previous operation events to the queue before receiving the response from entity. This is not the case when a short key is used.

[2020-11-21T20:38:32.423Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: d9a3ffab-f6e4-5651-8791-2fa5c59d6da5. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 58.
[2020-11-21T20:38:32.442Z] Count after reset is 0.
[2020-11-21T20:38:32.446Z] Date after reset is 00:00:00.
[2020-11-21T20:38:32.453Z] Incrementing entity.
[2020-11-21T20:38:32.472Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:adef9f84-c985-51b1-a283-00f816a74295. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 59.
[2020-11-21T20:38:32.492Z] 51308c0e2b554aca99130cd0f196b852: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 60.
[2020-11-21T20:38:32.534Z] Executed 'RestartOrchestrator' (Succeeded, Id=d8091903-3687-42bb-b6a1-48200fb9772c, Duration=193ms)
[2020-11-21T20:38:32.548Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 61.
[2020-11-21T20:38:42.353Z] Executing 'RestartCounter' (Reason='(null)', Id=5a8de1b4-b3b3-42a1-a5dd-e39a8e32c3a5)
[2020-11-21T20:38:42.357Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 62. TaskEventId: -1
[2020-11-21T20:38:42.361Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 63. TaskEventId: -1
[2020-11-21T20:38:42.371Z] Executed 'RestartCounter' (Succeeded, Id=5a8de1b4-b3b3-42a1-a5dd-e39a8e32c3a5, Duration=18ms)
[2020-11-21T20:38:42.386Z] Executing 'RestartCounter' (Reason='(null)', Id=105d4485-269b-492e-98af-6034480c0ddb)
[2020-11-21T20:38:42.389Z] Executed 'RestartCounter' (Succeeded, Id=105d4485-269b-492e-98af-6034480c0ddb, Duration=4ms)
[2020-11-21T20:38:52.367Z] Executing 'RestartCounter' (Reason='(null)', Id=2a4b5ab7-4ef0-4433-b3d5-544bb7d051ed)
[2020-11-21T20:38:52.380Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 64. TaskEventId: -1
[2020-11-21T20:38:52.404Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 65. TaskEventId: -1
[2020-11-21T20:38:52.418Z] Executed 'RestartCounter' (Succeeded, Id=2a4b5ab7-4ef0-4433-b3d5-544bb7d051ed, Duration=51ms)
[2020-11-21T20:38:52.437Z] Executing 'RestartCounter' (Reason='(null)', Id=8be0c18f-1c5b-43b9-9b20-b6ee2201597e)
[2020-11-21T20:38:52.452Z] Executed 'RestartCounter' (Succeeded, Id=8be0c18f-1c5b-43b9-9b20-b6ee2201597e, Duration=15ms)
[2020-11-21T20:39:17.331Z] Executing 'RestartCounter' (Reason='(null)', Id=6893f605-12aa-4c4e-a00b-55754e251d0e)
[2020-11-21T20:39:17.338Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 566436c5-f69d-5c28-b745-500f81f8a481 in 1.3498ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 66.
[2020-11-21T20:39:17.342Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation 929888b1-98f6-512e-8136-87559e837e0b in 0.5464ms. IsReplay: False. Input: (null). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 67.
[2020-11-21T20:39:17.346Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'Reset' operation 4467171e-91b0-5033-924e-17e162a6264e in 0.2784ms. IsReplay: False. Input: (null). Output: (null). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 68.
[2020-11-21T20:39:17.349Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation 225a693c-7ea4-533c-a580-8fe0020bd6d3 in 0.2368ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 69.
[2020-11-21T20:39:17.351Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation d9a3ffab-f6e4-5651-8791-2fa5c59d6da5 in 0.2529ms. IsReplay: False. Input: (null). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 70.
[2020-11-21T20:39:17.368Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed 'Increment' operation adef9f84-c985-51b1-a283-00f816a74295 in 1.0502ms. IsReplay: False. Input: (null). Output: (null). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 71.


Observation: The previous operations GetCount 566436c5-f69d-5c28-b745-500f81f8a481, GetDate 929888b1-98f6-512e-8136-87559e837e0b, Reset 4467171e-91b0-5033-924e-17e162a6264e, GetCount 225a693c-7ea4-533c-a580-8fe0020bd6d3, and GetDate d9a3ffab-f6e4-5651-8791-2fa5c59d6da5 are repeated. This is not the case when a short key is used.

[2020-11-21T20:39:17.373Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 72. TaskEventId: -1
[2020-11-21T20:39:17.376Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (196 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 73. TaskEventId: -1
[2020-11-21T20:39:17.379Z] Executed 'RestartCounter' (Succeeded, Id=6893f605-12aa-4c4e-a00b-55754e251d0e, Duration=47ms)
[2020-11-21T20:39:17.381Z] Executing 'RestartCounter' (Reason='(null)', Id=f36deddb-137c-48d9-a40c-3157071a5341)
[2020-11-21T20:39:17.394Z] Executed 'RestartCounter' (Succeeded, Id=f36deddb-137c-48d9-a40c-3157071a5341, Duration=12ms)
[2020-11-21T20:39:27.336Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=f96d7990-b7e5-4223-8897-512b5338e4ca)
[2020-11-21T20:39:27.361Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '566436c5-f69d-5c28-b745-500f81f8a481' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 74.
[2020-11-21T20:39:27.401Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '929888b1-98f6-512e-8136-87559e837e0b' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 75.
[2020-11-21T20:39:27.422Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '4467171e-91b0-5033-924e-17e162a6264e' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 76.
[2020-11-21T20:39:27.440Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a '225a693c-7ea4-533c-a580-8fe0020bd6d3' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 77.
[2020-11-21T20:39:27.448Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' saved a 'd9a3ffab-f6e4-5651-8791-2fa5c59d6da5' event to an in-memory queue. State: ExternalEventDropped. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 78.


Observation: Orchestrator writes the previous operation events to the queue before receiving the response from entity. This is not the case when a short key is used.

[2020-11-21T20:39:27.481Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: adef9f84-c985-51b1-a283-00f816a74295. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 79.
[2020-11-21T20:39:27.492Z] 51308c0e2b554aca99130cd0f196b852: Function 'RestartOrchestrator (Orchestrator)' completed. ContinuedAsNew: False. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 80. TaskEventId: -1


Observation: Orchestrator was completed after 2 minutes and 16 seconds. This is not the case when a short key is used. In that case the orchestrator instances complete in a couple of seconds (usually 3). In rare cases it takes 10-15 seconds.

[2020-11-21T20:39:27.515Z] Executed 'RestartOrchestrator' (Succeeded, Id=f96d7990-b7e5-4223-8897-512b5338e4ca, Duration=180ms)
[2020-11-21T20:39:37.348Z] Executing 'RestartCounter' (Reason='(null)', Id=aa8dadf5-8591-4b55-bc2c-5b34b8b5eba5)
[2020-11-21T20:39:37.353Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 81. TaskEventId: -1
[2020-11-21T20:39:37.357Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 82. TaskEventId: -1
[2020-11-21T20:39:37.367Z] Executed 'RestartCounter' (Succeeded, Id=aa8dadf5-8591-4b55-bc2c-5b34b8b5eba5, Duration=20ms)
[2020-11-21T20:39:37.383Z] Executing 'RestartCounter' (Reason='(null)', Id=e2a4cd45-8e12-46eb-a57a-db17348ec7e0)
[2020-11-21T20:39:37.404Z] Executed 'RestartCounter' (Succeeded, Id=e2a4cd45-8e12-46eb-a57a-db17348ec7e0, Duration=21ms)
[2020-11-21T20:39:49.749Z] Executing 'RestartCounter' (Reason='(null)', Id=02eaca4d-2fcd-421e-a150-d2fbc5faf564)
[2020-11-21T20:39:49.752Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 83. TaskEventId: -1
[2020-11-21T20:39:49.756Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 84. TaskEventId: -1
[2020-11-21T20:39:49.759Z] Executed 'RestartCounter' (Succeeded, Id=02eaca4d-2fcd-421e-a150-d2fbc5faf564, Duration=10ms)
[2020-11-21T20:39:49.763Z] Executing 'RestartCounter' (Reason='(null)', Id=286e7fbf-b063-4364-9402-e3ff46ce8e32)
[2020-11-21T20:39:49.765Z] Executed 'RestartCounter' (Succeeded, Id=286e7fbf-b063-4364-9402-e3ff46ce8e32, Duration=2ms)
[2020-11-21T20:39:59.762Z] Executing 'RestartCounter' (Reason='(null)', Id=fce27d15-14b5-419f-9065-14fc686931fb)
[2020-11-21T20:39:59.774Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 85. TaskEventId: -1
[2020-11-21T20:39:59.801Z] @restartcounter@/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group/providers/Microsoft.Web/sites/an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 86. TaskEventId: -1


Observation: Even though the orchestrator was completed the entity is being started constantly every ~30 seconds. Also subsequent triggers of the orchestrator take much longer time to complete. In one case it did not complete after 30 minutes. This is not the case when a short key is used.

### Expected behavior

The logs below are written to the console when the orchestrator `RestartOrchestrator` operates on the entity `RestartCounter` with a short key. The expactation is that the logs look similar when the entity has a long name (at least the time it takes to complete the orchestration instance). The places in the log which differ from actual behaviour are annotated.

[2020-11-21T22:24:27.875Z] Executing HTTP request: {
[2020-11-21T22:24:27.879Z] requestId: "1daed3ac-7c8f-4d41-bf5a-d19e9bc93135",
[2020-11-21T22:24:27.881Z] method: "POST",
[2020-11-21T22:24:27.884Z] userAgent: "PostmanRuntime/7.26.8",
[2020-11-21T22:24:27.885Z] uri: "/api/Alert"
[2020-11-21T22:24:27.892Z] }
[2020-11-21T22:24:28.054Z] Executing 'Alert' (Reason='This function was programmatically called via the host APIs.', Id=8e209b44-833a-49da-aac4-c3e0d9cdb703)
[2020-11-21T22:24:28.089Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' scheduled. Reason: NewInstance. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 2.
[2020-11-21T22:24:28.311Z] Executed 'Alert' (Succeeded, Id=8e209b44-833a-49da-aac4-c3e0d9cdb703, Duration=285ms)
[2020-11-21T22:24:28.382Z] Executed HTTP request: {
[2020-11-21T22:24:28.385Z] requestId: "1daed3ac-7c8f-4d41-bf5a-d19e9bc93135",
[2020-11-21T22:24:28.388Z] identities: "",
[2020-11-21T22:24:28.389Z] status: "200",
[2020-11-21T22:24:28.390Z] duration: "503"
[2020-11-21T22:24:28.419Z] }
[2020-11-21T22:24:28.509Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=1987d2de-845c-425f-bac7-e67e6a168e2b)
[2020-11-21T22:24:28.520Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' started. IsReplay: False. Input: (64 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 3. TaskEventId: -1
[2020-11-21T22:24:28.583Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:a05708f3-1a43-5d9a-ad21-7cfdecc12271. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 4.
[2020-11-21T22:24:28.587Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 5.
[2020-11-21T22:24:28.594Z] Executed 'RestartOrchestrator' (Succeeded, Id=1987d2de-845c-425f-bac7-e67e6a168e2b, Duration=87ms)
[2020-11-21T22:24:28.629Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 6.
[2020-11-21T22:24:28.822Z] Executing 'RestartCounter' (Reason='(null)', Id=12a2ffc9-1ceb-4adf-b8e9-83904985e51d)
[2020-11-21T22:24:28.844Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation a05708f3-1a43-5d9a-ad21-7cfdecc12271 in 9.303ms. IsReplay: False. Input: (null). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 7.
[2020-11-21T22:24:28.872Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (null). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 8. TaskEventId: -1
[2020-11-21T22:24:28.928Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 9. TaskEventId: -1
[2020-11-21T22:24:28.939Z] Executed 'RestartCounter' (Succeeded, Id=12a2ffc9-1ceb-4adf-b8e9-83904985e51d, Duration=118ms)
[2020-11-21T22:24:28.992Z] Executing 'RestartCounter' (Reason='(null)', Id=ef962020-b4fc-4c5b-aac3-a30df30521b5)
[2020-11-21T22:24:28.998Z] Executed 'RestartCounter' (Succeeded, Id=ef962020-b4fc-4c5b-aac3-a30df30521b5, Duration=6ms)
[2020-11-21T22:24:29.172Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=f0ecb38c-238e-4cf7-81d8-e54fa83bb469)
[2020-11-21T22:24:29.177Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: a05708f3-1a43-5d9a-ad21-7cfdecc12271. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 10.
[2020-11-21T22:24:29.191Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:bd7137c9-b49f-5621-b07b-0d8bf2f8083b. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 11.
[2020-11-21T22:24:29.234Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 12.
[2020-11-21T22:24:29.260Z] Executed 'RestartOrchestrator' (Succeeded, Id=f0ecb38c-238e-4cf7-81d8-e54fa83bb469, Duration=88ms)
[2020-11-21T22:24:29.283Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 13.
[2020-11-21T22:24:29.477Z] Executing 'RestartCounter' (Reason='(null)', Id=5a68e17d-df5c-4a46-93e9-ea463d97e1c8)
[2020-11-21T22:24:29.484Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation bd7137c9-b49f-5621-b07b-0d8bf2f8083b in 4.0098ms. IsReplay: False. Input: (1120 bytes). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 14.


Observation: The previous operation GetCount a05708f3-1a43-5d9a-ad21-7cfdecc12271 is not repeated. The same applies to all other operations below. None of the previous operations will be repeated. This is not the case when a long key is used.

[2020-11-21T22:24:29.488Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (1120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 15. TaskEventId: -1
[2020-11-21T22:24:29.513Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 16. TaskEventId: -1
[2020-11-21T22:24:29.529Z] Executed 'RestartCounter' (Succeeded, Id=5a68e17d-df5c-4a46-93e9-ea463d97e1c8, Duration=52ms)
[2020-11-21T22:24:29.536Z] Executing 'RestartCounter' (Reason='(null)', Id=4dce3762-62df-43dc-8e55-69733494f2d7)
[2020-11-21T22:24:29.542Z] Executed 'RestartCounter' (Succeeded, Id=4dce3762-62df-43dc-8e55-69733494f2d7, Duration=5ms)
[2020-11-21T22:24:29.807Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=ee3d6451-da99-4bae-b834-2a5839d88042)
[2020-11-21T22:24:29.812Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: bd7137c9-b49f-5621-b07b-0d8bf2f8083b. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 17.

Observation: Orchestrator does not write the previous operation event to the queue before receiving the response from entity. This applies to all other responses below. None of the previous events will be written to the queue. This is not the case when a long key is used.

[2020-11-21T22:24:29.818Z] Count is 0.
[2020-11-21T22:24:29.824Z] Date is 00:00:00.
[2020-11-21T22:24:29.843Z] Resetting entity.
[2020-11-21T22:24:29.850Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:afe6f9c0-8719-545f-8eba-a00a8d42c63a. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 18.
[2020-11-21T22:24:29.868Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 19.
[2020-11-21T22:24:29.906Z] Executed 'RestartOrchestrator' (Succeeded, Id=ee3d6451-da99-4bae-b834-2a5839d88042, Duration=98ms)
[2020-11-21T22:24:29.919Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 20.
[2020-11-21T22:24:30.037Z] Executing 'RestartCounter' (Reason='(null)', Id=305c1f0f-c991-4e95-aeff-bbdc627586db)
[2020-11-21T22:24:30.042Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed 'Reset' operation afe6f9c0-8719-545f-8eba-a00a8d42c63a in 1.4686ms. IsReplay: False. Input: (1120 bytes). Output: (null). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 21.
[2020-11-21T22:24:30.044Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (1120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 22. TaskEventId: -1
[2020-11-21T22:24:30.047Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 23. TaskEventId: -1
[2020-11-21T22:24:30.049Z] Executed 'RestartCounter' (Succeeded, Id=305c1f0f-c991-4e95-aeff-bbdc627586db, Duration=11ms)
[2020-11-21T22:24:30.051Z] Executing 'RestartCounter' (Reason='(null)', Id=6781fc49-ae5a-4b2e-b25e-7c5e83158878)
[2020-11-21T22:24:30.060Z] Executed 'RestartCounter' (Succeeded, Id=6781fc49-ae5a-4b2e-b25e-7c5e83158878, Duration=8ms)
[2020-11-21T22:24:30.231Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=d4e70e0e-71b2-4b85-8bcb-ac4ea697db12)
[2020-11-21T22:24:30.238Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: afe6f9c0-8719-545f-8eba-a00a8d42c63a. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 24.
[2020-11-21T22:24:30.244Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:be4f0c8c-61b0-5c06-b028-fbcf759485af. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 25.
[2020-11-21T22:24:30.249Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 26.
[2020-11-21T22:24:30.253Z] Executed 'RestartOrchestrator' (Succeeded, Id=d4e70e0e-71b2-4b85-8bcb-ac4ea697db12, Duration=22ms)
[2020-11-21T22:24:30.275Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 27.
[2020-11-21T22:24:30.517Z] Executing 'RestartCounter' (Reason='(null)', Id=d8e24432-4c04-4db2-8316-c6d0a7ef08ac)
[2020-11-21T22:24:30.534Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed 'GetCount' operation be4f0c8c-61b0-5c06-b028-fbcf759485af in 3.9912ms. IsReplay: False. Input: (1120 bytes). Output: (4 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 28.
[2020-11-21T22:24:30.559Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (1120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 29. TaskEventId: -1
[2020-11-21T22:24:30.579Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 30. TaskEventId: -1
[2020-11-21T22:24:30.616Z] Executed 'RestartCounter' (Succeeded, Id=d8e24432-4c04-4db2-8316-c6d0a7ef08ac, Duration=100ms)
[2020-11-21T22:24:30.647Z] Executing 'RestartCounter' (Reason='(null)', Id=39296666-0db8-4eca-a2fc-9cf73683aa85)
[2020-11-21T22:24:30.650Z] Executed 'RestartCounter' (Succeeded, Id=39296666-0db8-4eca-a2fc-9cf73683aa85, Duration=3ms)
[2020-11-21T22:24:30.821Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=034893c7-8c91-4d6e-9d70-d604f155065c)
[2020-11-21T22:24:30.833Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: be4f0c8c-61b0-5c06-b028-fbcf759485af. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 31.
[2020-11-21T22:24:30.840Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:2c6a73d2-0fbc-5d20-8dcd-00d349680d63. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 32.
[2020-11-21T22:24:30.842Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 33.
[2020-11-21T22:24:30.880Z] Executed 'RestartOrchestrator' (Succeeded, Id=034893c7-8c91-4d6e-9d70-d604f155065c, Duration=58ms)
[2020-11-21T22:24:30.885Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 34.
[2020-11-21T22:24:31.009Z] Executing 'RestartCounter' (Reason='(null)', Id=a2726ff1-e943-4f28-9c7d-514f10ceae59)
[2020-11-21T22:24:31.018Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed 'GetDate' operation 2c6a73d2-0fbc-5d20-8dcd-00d349680d63 in 1.4189ms. IsReplay: False. Input: (1120 bytes). Output: (84 bytes). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 35.
[2020-11-21T22:24:31.020Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (1120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 36. TaskEventId: -1
[2020-11-21T22:24:31.022Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (160 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 37. TaskEventId: -1
[2020-11-21T22:24:31.024Z] Executed 'RestartCounter' (Succeeded, Id=a2726ff1-e943-4f28-9c7d-514f10ceae59, Duration=15ms)
[2020-11-21T22:24:31.035Z] Executing 'RestartCounter' (Reason='(null)', Id=74be36ac-616e-4ffe-9452-a932e4e592a8)
[2020-11-21T22:24:31.044Z] Executed 'RestartCounter' (Succeeded, Id=74be36ac-616e-4ffe-9452-a932e4e592a8, Duration=9ms)
[2020-11-21T22:24:31.144Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=bd5609f6-b54a-4a82-aac1-5c15adc730ac)
[2020-11-21T22:24:31.150Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: 2c6a73d2-0fbc-5d20-8dcd-00d349680d63. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 38.
[2020-11-21T22:24:31.152Z] Count after reset is 0.
[2020-11-21T22:24:31.153Z] Date after reset is 00:00:00.
[2020-11-21T22:24:31.154Z] Incrementing entity.
[2020-11-21T22:24:31.156Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForEntityResponse:55d6b466-6c8d-580e-850b-a12dedb546e2. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 39.
[2020-11-21T22:24:31.158Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'restartcounter (Entity)' scheduled. Reason: RestartOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 40.
[2020-11-21T22:24:31.160Z] Executed 'RestartOrchestrator' (Succeeded, Id=bd5609f6-b54a-4a82-aac1-5c15adc730ac, Duration=16ms)
[2020-11-21T22:24:31.162Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 41.
[2020-11-21T22:24:31.283Z] Executing 'RestartCounter' (Reason='(null)', Id=4cb6ebc5-64c2-4039-a703-aad101c4b592)
[2020-11-21T22:24:31.290Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed 'Increment' operation 55d6b466-6c8d-580e-850b-a12dedb546e2 in 2.1563ms. IsReplay: False. Input: (1120 bytes). Output: (null). HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 42.
[2020-11-21T22:24:31.293Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' started. IsReplay: False. Input: (1120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 43. TaskEventId: -1
[2020-11-21T22:24:31.296Z] @restartcounter@an-app-service: Function 'restartcounter (Entity)' completed. ContinuedAsNew: True. IsReplay: False. Output: (196 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 44. TaskEventId: -1
[2020-11-21T22:24:31.302Z] Executed 'RestartCounter' (Succeeded, Id=4cb6ebc5-64c2-4039-a703-aad101c4b592, Duration=20ms)
[2020-11-21T22:24:31.306Z] Executing 'RestartCounter' (Reason='(null)', Id=5519ea7e-b190-441d-8de5-6d3d5a595e00)
[2020-11-21T22:24:31.328Z] Executed 'RestartCounter' (Succeeded, Id=5519ea7e-b190-441d-8de5-6d3d5a595e00, Duration=22ms)
[2020-11-21T22:24:31.451Z] Executing 'RestartOrchestrator' (Reason='(null)', Id=c7a5f714-d60e-497a-8cae-bbc6e7f829e5)
[2020-11-21T22:24:31.458Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' received an entity response. OperationId: 55d6b466-6c8d-580e-850b-a12dedb546e2. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 45.
[2020-11-21T22:24:31.464Z] b7e4d61b9cac4fc3a820794b93566e04: Function 'RestartOrchestrator (Orchestrator)' completed. ContinuedAsNew: False. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.3.1. SequenceNumber: 46. TaskEventId: -1
[2020-11-21T22:24:31.471Z] Executed 'RestartOrchestrator' (Succeeded, Id=c7a5f714-d60e-497a-8cae-bbc6e7f829e5, Duration=21ms)


Observation: Orchestrator instance runs very quick to completion. Even subsequent executions take roughly the same amount of time to complete. This is not the case when a long key is used.

Observation: After an instance of the orchestrator completes no entity is being started. This is not the case when a long key is used.

### Relevant source code snippets

```csharp
using System;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Azure.WebJobs;
using Microsoft.Azure.WebJobs.Extensions.DurableTask;
using Microsoft.Azure.WebJobs.Extensions.Http;
using Microsoft.Extensions.Logging;
using Newtonsoft.Json;

namespace FunctionApp1
{
    public interface IRestartCounter
    {
        Task<int> GetCount();

        Task<DateTime> GetDate();

        Task Increment();

        Task Reset();
    }

    [JsonObject(MemberSerialization.OptIn)]
    public class RestartCounter : IRestartCounter
    {
        [JsonProperty("count")]
        public int Count { get; set; }

        [JsonProperty("date")]
        public DateTime Date { get; set; }

        public Task<int> GetCount()
        {
            return Task.FromResult(this.Count);
        }

        public Task<DateTime> GetDate()
        {
            return Task.FromResult(this.Date);
        }

        public Task Increment()
        {
            this.Count++;
            this.Date = DateTime.UtcNow;
            return Task.CompletedTask;
        }

        public Task Reset()
        {
            this.Count = 0;
            this.Date = DateTime.MinValue;
            return Task.CompletedTask;
        }

        [FunctionName(nameof(RestartCounter))]
        public static Task Run([EntityTrigger] IDurableEntityContext ctx)
        {
            return ctx.DispatchAsync<RestartCounter>();
        }
    }

    public static class RestartOrchestrator
    {
        [FunctionName(nameof(RestartOrchestrator))]
        public static async Task RunOrchestratorAsync(
            [OrchestrationTrigger] IDurableOrchestrationContext context,
            ILogger logger)
        {
            logger = context.CreateReplaySafeLogger(logger);

            string resourceId = context.GetInput<string>();
            var entityId = new EntityId(nameof(RestartCounter), resourceId);
            IRestartCounter counter = context.CreateEntityProxy<IRestartCounter>(entityId);

            int count = await counter.GetCount();
            DateTime date = await counter.GetDate();

            logger.LogWarning("Count is {count}.", count);
            logger.LogWarning("Date is {date}.", date.ToLongTimeString());

            TimeSpan elapsedTimeSinceLastRestart = context.CurrentUtcDateTime - date;
            if (TimeSpan.FromSeconds(90) <= elapsedTimeSinceLastRestart)
            {
                logger.LogWarning("Resetting entity.");
                await counter.Reset();

                count = await counter.GetCount();
                date = await counter.GetDate();

                logger.LogWarning("Count after reset is {count}.", count);
                logger.LogWarning("Date after reset is {date}.", date.ToLongTimeString());
            }

            if (count <= 4)
            {
                TimeSpan fiveSeconds = TimeSpan.FromSeconds(5);
                TimeSpan waitTimeBetweenRestart = count == 0 ? TimeSpan.Zero : Math.Pow(2, count - 1) * fiveSeconds;

                if (waitTimeBetweenRestart <= elapsedTimeSinceLastRestart)
                {
                    // RESTART APP SERVICE HERE

                    logger.LogWarning("Incrementing entity.");
                    await counter.Increment();
                }
                else
                {
                    logger.LogWarning("Not enough waited.");
                }
            }
            else
            {
                logger.LogWarning("Too much restarts.");
            }
        }
    }

    public static class Alert
    {
        [FunctionName(nameof(Alert))]
        public static async Task<IActionResult> Run(
            [HttpTrigger(AuthorizationLevel.Anonymous, "POST", Route = null)] HttpRequest reqeuest,
            [DurableClient] IDurableClient starter,
            ILogger log)
        {
            _ = await starter.StartNewAsync<string>(nameof(RestartOrchestrator), "/subscriptions/00000000-0000-0000-0000-000000000000/resourceGroups/a-resource-group-name/providers/Microsoft.Web/sites/an-app-service");
            //_ = await starter.StartNewAsync<string>(nameof(RestartOrchestrator), "an-app-service");
            return new OkResult();
        }
    }
}

Known workarounds

Use a short name for entity key. Luckily this is possible in my use case since the name of an Azure App Service is unique over all subscriptions. For some other use cases choosing a short name might not be possible.

App Details

  • Durable Functions extension version (e.g. v1.8.3): 2.3.1
  • Azure Functions runtime version (1.0 or 2.0): 3.0.14916.0
  • Programming language used: C#
bug needs-discussion
Source
picture yvztzn

All 9 comments

Hmm, this is curious.

Looking at Table Storage documentation, partition keys are limited to 1KB, but your entity id doesn't appear to be quite hitting that yet at ~150 characters.

@sebastianburckhardt, any initial thoughts of what would cause a long entity key to cause duplicate operation executions?

@yvztzn, it may be that our internal telemetry would provide better details into what is going on here. You have given us the code, so we can try replicating this in the cloud, but note that with a holiday week at work and the team working hard to get v2.4.0 out the door, it may take some time before we have the resources to attempt reproducing this. If you could try this in Azure and provide us with the region + entity id + timestamp, that would speed up our ability to investigate this.

ConnorMcMahon picture ConnorMcMahon on 23 Nov 2020

I did a quick local test and I think this may be due to characters in instance id not being properly escaped in the Azure Storage backend.

This issue was reported in #1425, but I think it was never comprehensively fixed. The approach was to disallow characters in instance ids that would cause the backend to fail, and some tests were put into place, such as this one in the client:

throw new ArgumentException(nameof(entityKey), "Entity keys must not contain /, \\, #, ?, or control characters.");

But these tests do not cover the entire API, and these character restrictions are not documented.

I think it would be better to actually handle such characters correctly in the backend, by escaping them as needed when using them for storage keys. It seems wrong to burden the programmer with details of the backend (e.g. exactly what characters may be used in a storage key), especially since they may be using a non-Azure-Table backend at some point.

sebastianburckhardt picture sebastianburckhardt on 23 Nov 2020

@ConnorMcMahon looks like that @sebastianburckhardt already figured out what the root cause is. Do you still need a running instance somewhere on Azure?

yvztzn picture yvztzn on 25 Nov 2020

@yvztzn

You should not. I will change the name of the issue to reflect the root cause and add it to our backlog.

ConnorMcMahon picture ConnorMcMahon on 25 Nov 2020

I think we should tackle this issue in two steps, one for the short term and one for the long term.

First, let's make sure we are appropriately throwing an Argument Exception at all API surfaces where we need to, so customers can't accidentally create entities with invalid keys while the backend doesn't know how to handle them. This should be quick and easy, so we can target this for v2.4.1. One caveat is that we may want to make sure that we handle this in a Storage Provider specific context, as not all storage providers may have this limitation. At that point, we can treat the "bug" as resolved. @davidmrdavid, we may need to coordinate with the JS and Python language libraries to add these restrictions there as well.

In the long term, I think Sebastian is right that we can add support for keys with these characters if we handle proper escaping. This will take a bit longer to implement, and we can treat that as an "enhancement". Once we add support in the backend for these characters, then we can remove the restrictions on the APIs. We will have to wait until the extension release gets deployed via extension bundles before we can remove these API restrictions from the JS/Python libraries.

ConnorMcMahon picture ConnorMcMahon on 10 Dec 2020
👍1

Maybe you have already done this, but I think it's worth to check if the changes to the table access code are relatively easy - if so then the process of adding, testing, and then removing those API checks creates a lot of unnecessary work. I can take a quick look later today if you want.

sebastianburckhardt picture sebastianburckhardt on 10 Dec 2020

@sebastianburckhardt, you may be right there. Definitely worth an hour or two of investigation to prevent avoidable work if possible.

I think we will at least need to add those checks to the out-of-proc libraries, as we have found that extension release to widespread deployment for out-of-proc languages is in the order of a couple of months.

ConnorMcMahon picture ConnorMcMahon on 10 Dec 2020

FYI, I have started working on a solution for escaping & un-escaping invalid characters in row keys. It takes some work to apply this consistently everywhere (with queries and such) but I think it's worth it.

sebastianburckhardt picture sebastianburckhardt on 11 Dec 2020
👍1

PR to address this is here: https://github.com/Azure/durabletask/pull/481.

ConnorMcMahon picture ConnorMcMahon on 14 Dec 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

anhhnguyen206 picture anhhnguyen206  路  3Comments
val-janeiko picture val-janeiko  路  3Comments
mpaul31 picture mpaul31  路  3Comments
ethanroday picture ethanroday  路  4Comments
cgillum picture cgillum  路  4Comments