Log ScheduledEnqueueTimeUtc for timer messages in SentMessageLog#1319
Open
solankisamir wants to merge 1 commit intoAzure:mainfrom
Open
Log ScheduledEnqueueTimeUtc for timer messages in SentMessageLog#1319solankisamir wants to merge 1 commit intoAzure:mainfrom
solankisamir wants to merge 1 commit intoAzure:mainfrom
Conversation
When DurableTask creates a timer (CreateTimer orchestrator action), the ScheduledEnqueueTimeUtc is set on the Service Bus message but never logged to telemetry. This makes it difficult to investigate orchestration stalls caused by lost/delayed scheduled messages — investigators must infer the expected fire time from orchestration parameters. This change adds the ScheduledEnqueueTimeUtc to the existing SentMessageLog trace event for timer messages. Non-timer messages are unaffected (their ScheduledEnqueueTimeUtc is DateTime.MinValue and is omitted from the log). Before: 1 messages queued for Timer Message: abc123 <-1> After: 1 messages queued for Timer Message: abc123 <-1> ScheduledEnqueueTimeUtc:2026-03-12T03:04:00.0000000Z Context: Two Sev2 incidents (IcM 761467738, 758301760) involved Service Bus scheduled messages that were committed but never delivered, causing billing orchestrations to stall for 16-24 hours. Investigation required multiple rounds of Kusto queries to infer the expected fire time. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Member
Author
Contributor
There was a problem hiding this comment.
Pull request overview
Adds scheduled enqueue time telemetry for Service Bus timer messages by extending the existing ServiceBusOrchestrationService-SentMessageLog trace output, improving investigations of delayed/lost scheduled deliveries.
Changes:
- Appends
ScheduledEnqueueTimeUtcto the sent-message log entry when it’s present (non-DateTime.MinValue) - Keeps non-timer message logs unchanged by omitting the field when not scheduled
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
You can also share your feedback on Copilot code review. Take the survey.
| session.SessionId, | ||
| GetFormattedLog($@"{messages.Count.ToString()} messages queued for {messageType}: { | ||
| string.Join(",", messages.Select(m => $"{m.Message.MessageId} <{m.Action?.Event.EventId.ToString()}>"))}")); | ||
| string.Join(",", messages.Select(m => $"{m.Message.MessageId} <{m.Action?.Event.EventId.ToString()}>{(m.Message.ScheduledEnqueueTimeUtc > DateTime.MinValue ? $" ScheduledEnqueueTimeUtc:{m.Message.ScheduledEnqueueTimeUtc:O}" : "")}"))}")); |
| session.SessionId, | ||
| GetFormattedLog($@"{messages.Count.ToString()} messages queued for {messageType}: { | ||
| string.Join(",", messages.Select(m => $"{m.Message.MessageId} <{m.Action?.Event.EventId.ToString()}>"))}")); | ||
| string.Join(",", messages.Select(m => $"{m.Message.MessageId} <{m.Action?.Event.EventId.ToString()}>{(m.Message.ScheduledEnqueueTimeUtc > DateTime.MinValue ? $" ScheduledEnqueueTimeUtc:{m.Message.ScheduledEnqueueTimeUtc:O}" : "")}"))}")); |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
When DurableTask creates a timer (\CreateTimer\ orchestrator action), the \ScheduledEnqueueTimeUtc\ is set on the Service Bus message but never logged to telemetry. This makes it difficult to investigate orchestration stalls caused by lost or delayed scheduled messages — investigators must infer the expected fire time from orchestration parameters (\BillingPeriod, \TimeShift, previous \TimerFired\ timestamps).
Context
Two Sev2 incidents (IcM 761467738, IcM 758301760) involved Service Bus scheduled messages that were committed successfully but never delivered, causing billing eternal orchestrations to stall silently for 16–24 hours. Investigation required multiple rounds of Kusto queries across \DurableTask, \Billing, \Orchestration, and \TaskHubKpiRaw\ tables to infer the expected fire time and confirm the message was lost.
Solution
Add the \ScheduledEnqueueTimeUtc\ to the existing \ServiceBusOrchestrationService-SentMessageLog\ trace event for timer messages. Non-timer messages (worker, sub-orchestration) are unaffected since their \ScheduledEnqueueTimeUtc\ is \DateTime.MinValue\ and is omitted from the log.
Before:
\
1 messages queued for Timer Message: abc123 <-1>
\\
After:
\
1 messages queued for Timer Message: abc123 <-1> ScheduledEnqueueTimeUtc:2026-03-12T03:04:00.0000000Z
\\
Change
Single line change in \LogSentMessages()\ in \ServiceBusOrchestrationService.cs\ — appends the scheduled time when present.
Testing