microsoft / microsoft/durabletask-netherite
Activity Function started multiple times before completion
Nobody has claimed this yet.
- Dominant language
- C#
- Stars
- 239
- Forks
- 37
- Avg merge
- 1d 10h
- Merged PRs (30d)
- 2
Description
Summary:
We're observing instances where the same Activity Function, is being invoked multiple times before completing.
Additional information:
This Activity Function is started by an Orchestrator that awaits its completion. Although the Activity Function took around 35 seconds to be completely executed (when it succeeded), the Orchestrator's overall duration was more than 35 minutes.
From the correlated dependency logs, each time the Activity Function is invoked, it makes some progress, but it doesn't fully finish. There are no exceptions or errors during the processing; the Function seems to just "die" all of a sudden, and it is started again at a later time. It finally completed the execution more than 33 minutes after it was first invoked.
Logs:
The series of logs from the execution environment that show the recurring invocation of the Activity Function without successful completion:
4/30/2024, 11:19:16.877 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=d9480089-03b2-43c3-bb43-1ae28422bf90)
4/30/2024, 11:20:20.344 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=9635f32b-d150-41f1-98a1-7ac11e254a79)
4/30/2024, 11:24:45.411 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=59e01faf-f031-427c-a5db-4c59f7ea32f2)
4/30/2024, 11:25:36.743 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=cbd95782-2130-4385-a6c9-655e46bbd0e4)
4/30/2024, 11:28:45.263 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=25923d2c-9df4-47a2-824d-5f33c5b57489)
4/30/2024, 11:30:49.465 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=90e1f92f-e204-44f7-967a-884196c05952)
4/30/2024, 11:37:34.184 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=858b82c5-7691-40e4-940b-4ee405e2201c)
4/30/2024, 11:40:32.827 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=0e8b82a6-fc7a-4b92-84e6-10c03711c4c9)
4/30/2024, 11:44:36.547 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=611be298-bdb1-48eb-888e-1192e040d7d9)
4/30/2024, 11:45:51.290 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=68763aed-1b55-40e6-848c-48070bb23520)
4/30/2024, 11:47:25.412 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=4cb06969-3175-464e-8c8a-0c653957c43d)
4/30/2024, 11:48:57.625 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=c070d3ff-b8df-4f1a-a420-7852b16b936e)
4/30/2024, 11:50:28.654 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=83f41053-62a0-46db-b961-f39d40d2e4f5)
4/30/2024, 11:52:12.297 AM
Executing 'StartOfDayUpsertActivity' (Reason='(null)', Id=49445402-c24e-4066-9922-fca6a2c5e9b5)
4/30/2024, 11:52:45.042 AM
Executed 'StartOfDayUpsertActivity' (Succeeded, Id=49445402-c24e-4066-9922-fca6a2c5e9b5, Duration=34883ms)
At the same time, we observed various types of warnings, such as performance issues, storage conflicts, timeouts, and resource utilization alerts, that might be related to the unexpected behaviour described above. Here are some examples of such warnings:
Error response [8959bebe-ae91-4a2a-addb-8fd3476e538e] 409 The specified container already exists. (02.6s) Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0 x-ms-request-id:5599b6e0-301e-0061-73f0-9aa36d000000 x-ms-client-request-id:8959bebe-ae91-4a2a-addb-8fd3476e538e x-ms-version:2022-11-02 x-ms-error-code:ContainerAlreadyExists Date:Tue, 30 Apr 2024 11:19:14 GMT Content-Length:230 Content-Type:application/xml
Error response [2badf8bd-5897-48be-9fb5-9f2c29b52033] 409 There is already a lease present. (02.0s) Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0 x-ms-request-id:4885e259-c01e-0038-5ff0-9a24ee000000 x-ms-client-request-id:2badf8bd-5897-48be-9fb5-9f2c29b52033 x-ms-version:2022-11-02 x-ms-error-code:LeaseAlreadyPresent Date:Tue, 30 Apr 2024 11:19:15 GMT Content-Length:221 Content-Type:application/xml
Part00 Performance issue detected: storage operation PageBlobClient.DownloadStreamingAsync (ReadFromDevice) took 1.5s on attempt 1, which is excessive; id=7213 position=51179008 length=3584 operationReadRange=[51179008, 51182592]
Part10 Performance issue detected: RenewLeaseAsync took 2.4s, which is excessive; -11.871818500000003s past expiry
[HostMonitor] Host CPU threshold exceeded (87 >= 80)
Possible thread pool starvation detected.
Part01.0173103172 Dropped query 4890768R16 during recovery because it has timed out
Client.cc4e2ab Request cc4e2abR3 for partition 01 timed out
What could be the cause of the Activity Function not being completed, and started over and over again? And how can this be prevented?
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start with the StartOfDayUpsertActivity execution sequence and correlate its invocation IDs with the storage conflict, lease renewal, timeout, CPU, and thread-pool warnings in the logs. Determine why the activity is interrupted and replayed, then document a reproducible cause and prevention guidance for the reported behavior.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- azure, csharp
- Domain
- backend, cloud, distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100