From 13f9a1debb54063256cb8c849108f00a0d1be710 Mon Sep 17 00:00:00 2001 From: Copilot <223556219+Copilot@users.noreply.github.com> Date: Wed, 22 Apr 2026 09:07:15 +0000 Subject: [PATCH] [copilot-finds] Bug: Fix processNewEventsForTracing missing spans for same-batch events processNewEventsForTracing() only indexed pastEvents when building its scheduling-event lookup maps. When a task was scheduled and completed within the same event batch (both in newEvents), the corresponding tracing span was silently dropped because the scheduling event was never indexed. Fix: also index newEvents into the lookup maps so that same-batch completions can find their scheduling counterparts. Added 4 new test cases covering same-batch scenarios for: - Activity scheduled + completed in same batch - Activity scheduled + failed in same batch - Sub-orchestration created + completed in same batch - Timer created + fired in same batch Fixes #229 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../src/tracing/trace-helper.ts | 17 ++- packages/durabletask-js/test/tracing.spec.ts | 106 ++++++++++++++++++ 2 files changed, 122 insertions(+), 1 deletion(-) diff --git a/packages/durabletask-js/src/tracing/trace-helper.ts b/packages/durabletask-js/src/tracing/trace-helper.ts index aecbb46..9b8b291 100644 --- a/packages/durabletask-js/src/tracing/trace-helper.ts +++ b/packages/durabletask-js/src/tracing/trace-helper.ts @@ -461,7 +461,11 @@ export function processNewEventsForTracing( if (!orchestrationSpan) return; if (!getTracingContext()) return; - // Build lookup maps from past events + // Build lookup maps from both past and new events. + // Including newEvents is necessary because scheduling events (TaskScheduled, + // SubOrchestrationInstanceCreated, TimerCreated) and their corresponding + // completion events can arrive in the same batch when tasks complete quickly. + // Without indexing newEvents, these same-batch completions produce no tracing span. const taskScheduledEvents = new Map(); const subOrchCreatedEvents = new Map(); const timerCreatedEvents = new Map(); @@ -477,6 +481,17 @@ export function processNewEventsForTracing( } } + for (const event of newEvents) { + const eventId = event.getEventid(); + if (event.hasTaskscheduled()) { + taskScheduledEvents.set(eventId, event); + } else if (event.hasSuborchestrationinstancecreated()) { + subOrchCreatedEvents.set(eventId, event); + } else if (event.hasTimercreated()) { + timerCreatedEvents.set(eventId, event); + } + } + // Process new events for completions, failures, and timer firings for (const newEvent of newEvents) { if (newEvent.hasTaskcompleted()) { diff --git a/packages/durabletask-js/test/tracing.spec.ts b/packages/durabletask-js/test/tracing.spec.ts index 4e2dfa0..437cebc 100644 --- a/packages/durabletask-js/test/tracing.spec.ts +++ b/packages/durabletask-js/test/tracing.spec.ts @@ -1589,5 +1589,111 @@ describe("Retroactive span emission", () => { // Only the parent orch span should exist expect(spans.length).toBe(1); }); + + it("should emit activity span when TaskScheduled and TaskCompleted arrive in the same newEvents batch", () => { + const tracer = otel.trace.getTracer(TRACER_NAME); + const orchSpan = tracer.startSpan("test-orch"); + const schedulingTime = new Date("2025-06-01T08:00:00Z"); + + // Both scheduling and completion are in newEvents (no pastEvents) + const scheduledEvent = makeHistoryEvent(1, schedulingTime); + const taskScheduled = new pb.TaskScheduledEvent(); + taskScheduled.setName("FastActivity"); + scheduledEvent.setTaskscheduled(taskScheduled); + + const completedEvent = makeHistoryEvent(2); + const taskCompleted = new pb.TaskCompletedEvent(); + taskCompleted.setTaskscheduledid(1); + completedEvent.setTaskcompleted(taskCompleted); + + processNewEventsForTracing(orchSpan, [], [scheduledEvent, completedEvent], "same-batch-instance", "SameBatchOrch"); + orchSpan.end(); + + const spans = exporter.getFinishedSpans(); + const activitySpan = spans.find((s: any) => s.name === "activity:FastActivity"); + expect(activitySpan).toBeDefined(); + expect(activitySpan!.kind).toBe(otel.SpanKind.CLIENT); + expect(activitySpan!.attributes[DurableTaskAttributes.TASK_INSTANCE_ID]).toBe("same-batch-instance"); + expect(activitySpan!.startTime[0]).toBe(Math.floor(schedulingTime.getTime() / 1000)); + }); + + it("should emit activity span with error when TaskScheduled and TaskFailed arrive in the same newEvents batch", () => { + const tracer = otel.trace.getTracer(TRACER_NAME); + const orchSpan = tracer.startSpan("test-orch"); + + const scheduledEvent = makeHistoryEvent(3, new Date()); + const taskScheduled = new pb.TaskScheduledEvent(); + taskScheduled.setName("FailFastActivity"); + scheduledEvent.setTaskscheduled(taskScheduled); + + const failedEvent = makeHistoryEvent(4); + const taskFailed = new pb.TaskFailedEvent(); + taskFailed.setTaskscheduledid(3); + const failureDetails = new pb.TaskFailureDetails(); + failureDetails.setErrormessage("Activity not registered"); + taskFailed.setFailuredetails(failureDetails); + failedEvent.setTaskfailed(taskFailed); + + processNewEventsForTracing(orchSpan, [], [scheduledEvent, failedEvent], "fail-batch-instance", "FailBatchOrch"); + orchSpan.end(); + + const spans = exporter.getFinishedSpans(); + const activitySpan = spans.find((s: any) => s.name === "activity:FailFastActivity"); + expect(activitySpan).toBeDefined(); + expect(activitySpan!.status.code).toBe(otel.SpanStatusCode.ERROR); + expect(activitySpan!.status.message).toBe("Activity not registered"); + }); + + it("should emit sub-orchestration span when created and completed arrive in the same newEvents batch", () => { + const tracer = otel.trace.getTracer(TRACER_NAME); + const orchSpan = tracer.startSpan("test-orch"); + const creationTime = new Date("2025-06-01T09:00:00Z"); + + const createdEvent = makeHistoryEvent(5, creationTime); + const subOrchCreated = new pb.SubOrchestrationInstanceCreatedEvent(); + subOrchCreated.setName("QuickChild"); + createdEvent.setSuborchestrationinstancecreated(subOrchCreated); + + const completedEvent = makeHistoryEvent(6); + const subOrchCompleted = new pb.SubOrchestrationInstanceCompletedEvent(); + subOrchCompleted.setTaskscheduledid(5); + completedEvent.setSuborchestrationinstancecompleted(subOrchCompleted); + + processNewEventsForTracing(orchSpan, [], [createdEvent, completedEvent], "sub-batch-instance", "SubBatchOrch"); + orchSpan.end(); + + const spans = exporter.getFinishedSpans(); + const subOrchSpan = spans.find((s: any) => s.name === "orchestration:QuickChild"); + expect(subOrchSpan).toBeDefined(); + expect(subOrchSpan!.kind).toBe(otel.SpanKind.CLIENT); + expect(subOrchSpan!.startTime[0]).toBe(Math.floor(creationTime.getTime() / 1000)); + }); + + it("should emit timer span when TimerCreated and TimerFired arrive in the same newEvents batch", () => { + const tracer = otel.trace.getTracer(TRACER_NAME); + const orchSpan = tracer.startSpan("test-orch"); + const timerCreationTime = new Date("2025-06-01T10:00:00Z"); + const timerFireTime = new Date("2025-06-01T10:00:01Z"); + + const createdEvent = makeHistoryEvent(7, timerCreationTime); + createdEvent.setTimercreated(new pb.TimerCreatedEvent()); + + const firedEvent = makeHistoryEvent(8); + const timerFired = new pb.TimerFiredEvent(); + timerFired.setTimerid(7); + const fireAtTs = new Timestamp(); + fireAtTs.fromDate(timerFireTime); + timerFired.setFireat(fireAtTs); + firedEvent.setTimerfired(timerFired); + + processNewEventsForTracing(orchSpan, [], [createdEvent, firedEvent], "timer-batch-instance", "TimerBatchOrch"); + orchSpan.end(); + + const spans = exporter.getFinishedSpans(); + const timerSpan = spans.find((s: any) => s.name === "orchestration:TimerBatchOrch:timer"); + expect(timerSpan).toBeDefined(); + expect(timerSpan!.kind).toBe(otel.SpanKind.INTERNAL); + expect(timerSpan!.startTime[0]).toBe(Math.floor(timerCreationTime.getTime() / 1000)); + }); }); });