From fc3e827f7567af654a85ade8d5825dfb0689bd46 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 7 Jul 2025 16:29:58 +0000 Subject: [PATCH 1/3] Initial plan From 0967f5c6254f59ddd9f3e0e1d9347f3612e2e7b1 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 7 Jul 2025 16:40:10 +0000 Subject: [PATCH 2/3] Fix trackDependency default timing to treat current time as end time Co-authored-by: JacksonWeber <47067795+JacksonWeber@users.noreply.github.com> --- src/shim/telemetryClient.ts | 6 +- test/unitTests/shim/telemetryClient.tests.ts | 74 ++++++++++++++++++++ 2 files changed, 78 insertions(+), 2 deletions(-) diff --git a/src/shim/telemetryClient.ts b/src/shim/telemetryClient.ts index 1aed99eb..da372770 100644 --- a/src/shim/telemetryClient.ts +++ b/src/shim/telemetryClient.ts @@ -225,8 +225,10 @@ export class TelemetryClient { if (!this._isInitialized) { this.initialize(); } - const startTime = telemetry.time || new Date(); - const endTime = startTime.getTime() + telemetry.duration; + // For trackDependency, when time is not specified, treat current time as END time + // since this method is called after the dependency operation has completed + const endTime = telemetry.time ? telemetry.time.getTime() + telemetry.duration : Date.now(); + const startTime = telemetry.time || new Date(endTime - telemetry.duration); if (telemetry && !telemetry.target && telemetry.data) { // url.parse().host returns null for non-urls, // making this essentially a no-op in those cases diff --git a/test/unitTests/shim/telemetryClient.tests.ts b/test/unitTests/shim/telemetryClient.tests.ts index 63e27037..628b1d91 100644 --- a/test/unitTests/shim/telemetryClient.tests.ts +++ b/test/unitTests/shim/telemetryClient.tests.ts @@ -240,6 +240,80 @@ describe("shim/TelemetryClient", () => { assert.equal(spans[0].attributes[SEMATTRS_RPC_SYSTEM], "RPC"); }); + it("trackDependency default timing - should treat current time as end time", async () => { + const beforeCall = Date.now(); + const telemetry: DependencyTelemetry = { + name: "TestTimingDependency", + duration: 1000, // 1 second + resultCode: "200", + data: "http://api.example.com", + dependencyTypeName: "HTTP", + success: true, + }; + // Call trackDependency without specifying 'time' - should default to current time as END time + client.trackDependency(telemetry); + const afterCall = Date.now(); + + await tracerProvider.forceFlush(); + const spans = testProcessor.spansProcessed; + assert.equal(spans.length, 1); + assert.equal(spans[0].name, "TestTimingDependency"); + + // Convert span times from hrTime to milliseconds for comparison + const spanStartMs = spans[0].startTime[0] * 1000 + spans[0].startTime[1] / 1_000_000; + const spanEndMs = spans[0].endTime[0] * 1000 + spans[0].endTime[1] / 1_000_000; + + // Duration should match the specified duration + const actualDuration = spanEndMs - spanStartMs; + assert.ok(Math.abs(actualDuration - 1000) < 10, `Expected duration ~1000ms, got ${actualDuration}ms`); + + // End time should be close to when we called trackDependency (within reasonable tolerance) + assert.ok(spanEndMs >= beforeCall && spanEndMs <= afterCall + 50, + `End time ${spanEndMs} should be between ${beforeCall} and ${afterCall + 50}`); + + // Start time should be approximately end time minus duration + const expectedStartMs = spanEndMs - 1000; + assert.ok(Math.abs(spanStartMs - expectedStartMs) < 10, + `Start time ${spanStartMs} should be close to ${expectedStartMs}`); + }); + + it("trackDependency with custom time - should respect provided start time", async () => { + const customStartTime = new Date(Date.now() - 5000); // 5 seconds ago + const telemetry: DependencyTelemetry = { + name: "CustomTimeDependency", + duration: 2000, // 2 seconds + resultCode: "200", + data: "http://custom.example.com", + dependencyTypeName: "HTTP", + success: true, + time: customStartTime + }; + + client.trackDependency(telemetry); + + await tracerProvider.forceFlush(); + const spans = testProcessor.spansProcessed; + assert.equal(spans.length, 1); + assert.equal(spans[0].name, "CustomTimeDependency"); + + // Convert span times from hrTime to milliseconds for comparison + const spanStartMs = spans[0].startTime[0] * 1000 + spans[0].startTime[1] / 1_000_000; + const spanEndMs = spans[0].endTime[0] * 1000 + spans[0].endTime[1] / 1_000_000; + + // Duration should match the specified duration + const actualDuration = spanEndMs - spanStartMs; + assert.ok(Math.abs(actualDuration - 2000) < 10, `Expected duration ~2000ms, got ${actualDuration}ms`); + + // Start time should match the custom time provided + assert.ok(Math.abs(spanStartMs - customStartTime.getTime()) < 10, + `Start time ${spanStartMs} should be close to custom time ${customStartTime.getTime()}`); + + // End time should be start time plus duration + const expectedEndMs = customStartTime.getTime() + 2000; + assert.ok(Math.abs(spanEndMs - expectedEndMs) < 10, + `End time ${spanEndMs} should be close to ${expectedEndMs}`); + }); + it("trackRequest", async () => { const telemetry: RequestTelemetry = { id: "123456", From 7f1c8144c7b46179725793d5840f027cb3ab4eff Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 7 Jul 2025 16:50:14 +0000 Subject: [PATCH 3/3] Fix trackRequest timing issue - treat current time as end time when time not specified Co-authored-by: JacksonWeber <47067795+JacksonWeber@users.noreply.github.com> --- src/shim/telemetryClient.ts | 6 +- test/unitTests/shim/telemetryClient.tests.ts | 69 ++++++++++++++++++++ 2 files changed, 73 insertions(+), 2 deletions(-) diff --git a/src/shim/telemetryClient.ts b/src/shim/telemetryClient.ts index da372770..fbf97988 100644 --- a/src/shim/telemetryClient.ts +++ b/src/shim/telemetryClient.ts @@ -174,8 +174,10 @@ export class TelemetryClient { if (!this._isInitialized) { this.initialize(); } - const startTime = telemetry.time || new Date(); - const endTime = startTime.getTime() + telemetry.duration; + // For trackRequest, when time is not specified, treat current time as END time + // since this method is called after the request operation has completed + const endTime = telemetry.time ? telemetry.time.getTime() + telemetry.duration : Date.now(); + const startTime = telemetry.time || new Date(endTime - telemetry.duration); const ctx = context.active(); const attributes: Attributes = { diff --git a/test/unitTests/shim/telemetryClient.tests.ts b/test/unitTests/shim/telemetryClient.tests.ts index 628b1d91..fa0ead50 100644 --- a/test/unitTests/shim/telemetryClient.tests.ts +++ b/test/unitTests/shim/telemetryClient.tests.ts @@ -353,6 +353,75 @@ describe("shim/TelemetryClient", () => { assert.equal(spans[0].spanContext().traceId, customId); }); + it("trackRequest default timing - should treat current time as end time", async () => { + const beforeCall = Date.now(); + const telemetry: RequestTelemetry = { + name: "TestTimingRequest", + duration: 1500, // 1.5 seconds + resultCode: "200", + url: "http://api.example.com/users", + success: true, + }; + // Call trackRequest without specifying 'time' - should default to current time as END time + client.trackRequest(telemetry); + const afterCall = Date.now(); + + await tracerProvider.forceFlush(); + const spans = testProcessor.spansProcessed; + assert.equal(spans.length, 1); + assert.equal(spans[0].name, "TestTimingRequest"); + + // Convert span times from hrTime to milliseconds for comparison + const spanStartMs = spans[0].startTime[0] * 1000 + spans[0].startTime[1] / 1_000_000; + const spanEndMs = spans[0].endTime[0] * 1000 + spans[0].endTime[1] / 1_000_000; + + // Duration should match the specified duration + const actualDuration = spanEndMs - spanStartMs; + assert.ok(Math.abs(actualDuration - 1500) < 10, `Expected duration ~1500ms, got ${actualDuration}ms`); + + // End time should be close to when we called trackRequest (within reasonable tolerance) + assert.ok(spanEndMs >= beforeCall && spanEndMs <= afterCall + 50, + `End time ${spanEndMs} should be between ${beforeCall} and ${afterCall + 50}`); + + // Start time should be calculated as end time - duration + const expectedStartMs = spanEndMs - 1500; + assert.ok(Math.abs(spanStartMs - expectedStartMs) < 10, + `Start time ${spanStartMs} should be close to ${expectedStartMs}`); + }); + + it("trackRequest with custom time - should respect provided start time", async () => { + const customStartTime = new Date(Date.now() - 3000); // 3 seconds ago + const telemetry: RequestTelemetry = { + name: "CustomTimeRequest", + duration: 1200, // 1.2 seconds + resultCode: "201", + url: "http://custom.example.com/data", + success: true, + time: customStartTime + }; + + client.trackRequest(telemetry); + + await tracerProvider.forceFlush(); + const spans = testProcessor.spansProcessed; + assert.equal(spans.length, 1); + assert.equal(spans[0].name, "CustomTimeRequest"); + + // Convert span times from hrTime to milliseconds for comparison + const spanStartMs = spans[0].startTime[0] * 1000 + spans[0].startTime[1] / 1_000_000; + const spanEndMs = spans[0].endTime[0] * 1000 + spans[0].endTime[1] / 1_000_000; + + // Start time should match the provided custom time + const expectedStartMs = customStartTime.getTime(); + assert.ok(Math.abs(spanStartMs - expectedStartMs) < 10, + `Start time ${spanStartMs} should be close to ${expectedStartMs}`); + + // End time should be start time + duration + const expectedEndMs = customStartTime.getTime() + 1200; + assert.ok(Math.abs(spanEndMs - expectedEndMs) < 10, + `End time ${spanEndMs} should be close to ${expectedEndMs}`); + }); + it("trackDependency with custom id sets traceId", async () => { const customId = "custom-dependency-trace-id-abcdef"; const telemetry: DependencyTelemetry = {