Skip to content

Commit 3e0fda9

Browse files
szegedirochdev
authored andcommitted
test(profiler): fix Profiler telemetry flake (#8114)
* test(profiler): fix Profiler telemetry flake The integration test `profiler > Profiler telemetry > sends profiler API telemetry` accounts for the bulk of recent Profiling flakes. Two issues: 1. `assertTelemetryReceived` in fake-agent.js filters only by `request_type`, but the tracer's NamespaceManager emits a `generate-metrics` payload per namespace (`tracers`, `profilers`, `appsec`, ...). Tracer-namespace messages tripped the inner `assert.strictEqual(pp.namespace, 'profilers')` check, polluting the collected `errors[]` with confusing `'tracers' !== 'profilers'` noise on any failure. 2. The `requestCount <= 3` upper bound was off-by-one: with DD_PROFILING_UPLOAD_PERIOD=1 and TEST_DURATION_MS=2500, the periodic-vs-shutdown race the comment already calls out can yield 4 uploads. Add an optional `namespace` parameter to `assertTelemetryReceived` that filters at the same point as `requestType` (backward-compatible, no existing callers pass a 6th argument). Use it from the three profiler telemetry assertions and bump the bound to `<= 4`. * refactor(test): convert assertTelemetryReceived to a single options arg The signature had grown to six positional parameters with a built-in overload that shifted them when `fn` was omitted, which was hard to read and easy to get wrong. Convert to a single options object with defaulted properties (`fn`, `requestType`, `timeout`, `expectedMessageCount`, `resolveAtFirstSuccess`, `namespace`) and update all 16 call sites. No behavior change; only the call shape. * fix(test): preserve never-resolve semantics for SSI-absent telemetry check The `records profile on process exit` test wraps a telemetry assertion in `expectTimeout`, which requires the inner promise to reject with a timeout. The original 2-arg call relied on a quirk in the helper's positional overload that left `expectedMessageCount` at 30000, making the promise effectively unresolvable. The options-object refactor restored the documented default of 1, so the first matching `generate-metrics` message resolved the promise and broke the test. Make the intent explicit with `expectedMessageCount: Infinity` and a comment explaining why.
1 parent 831a22d commit 3e0fda9

11 files changed

Lines changed: 320 additions & 257 deletions

integration-tests/appsec/endpoints-collection.spec.js

Lines changed: 19 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -138,21 +138,26 @@ describe('Endpoints collection', () => {
138138

139139
const expectedMessageCount = framework === 'express' ? 7 : 4
140140

141-
const telemetryPromise = agent.assertTelemetryReceived(({ payload }) => {
142-
isFirstFlags.push(Boolean(payload.payload.is_first))
143-
144-
if (payload.payload.endpoints) {
145-
payload.payload.endpoints.forEach(endpoint => {
146-
endpointsFound.push({
147-
method: endpoint.method,
148-
path: endpoint.path,
149-
type: endpoint.type,
150-
operation_name: endpoint.operation_name,
151-
resource_name: endpoint.resource_name,
141+
const telemetryPromise = agent.assertTelemetryReceived({
142+
fn: ({ payload }) => {
143+
isFirstFlags.push(Boolean(payload.payload.is_first))
144+
145+
if (payload.payload.endpoints) {
146+
payload.payload.endpoints.forEach(endpoint => {
147+
endpointsFound.push({
148+
method: endpoint.method,
149+
path: endpoint.path,
150+
type: endpoint.type,
151+
operation_name: endpoint.operation_name,
152+
resource_name: endpoint.resource_name,
153+
})
152154
})
153-
})
154-
}
155-
}, 'app-endpoints', 5_000, expectedMessageCount)
155+
}
156+
},
157+
requestType: 'app-endpoints',
158+
timeout: 5_000,
159+
expectedMessageCount,
160+
})
156161

157162
proc = await spawnProc(appFile, {
158163
cwd,

integration-tests/bun/bun.spec.js

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -106,7 +106,7 @@ describe('Bun runtime smoke tests', function () {
106106
})
107107

108108
it('should emit app-started telemetry under Bun', async () => {
109-
const telemetryPromise = agent.assertTelemetryReceived('app-started', 20_000, 1)
109+
const telemetryPromise = agent.assertTelemetryReceived({ requestType: 'app-started', timeout: 20_000 })
110110

111111
const [bunResult] = await Promise.all([
112112
runBun('bun/init-telemetry.js', {

integration-tests/helpers/fake-agent.js

Lines changed: 19 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -213,30 +213,25 @@ module.exports = class FakeAgent extends EventEmitter {
213213
/**
214214
* Assert that a telemetry message is received.
215215
*
216-
* @overload
217-
* @param {string} requestType - The request type to assert.
218-
* @param {number} [timeout=30_000] - The timeout in milliseconds.
219-
* @param {number} [expectedMessageCount=1] - The number of messages to expect.
220-
* @returns {Promise<void>} A promise that resolves when the telemetry message of type `requestType` is received.
216+
* @param {object} options
217+
* @param {Function} [options.fn] - Function called with each matching telemetry message. If it throws,
218+
* the error is collected and the listener stays alive for the next message. Defaults to a no-op.
219+
* @param {string} options.requestType - The telemetry request type to match.
220+
* @param {number} [options.timeout=30_000] - Timeout in milliseconds before the promise rejects.
221+
* @param {number} [options.expectedMessageCount=1] - Number of matching messages to wait for.
222+
* @param {boolean} [options.resolveAtFirstSuccess=false] - Resolve as soon as `fn` first runs without throwing.
223+
* @param {string} [options.namespace] - If set, only consider messages whose payload namespace equals this value.
224+
* @returns {Promise<void>} A promise that resolves when the expected telemetry messages are received and `fn` has
225+
* run successfully. If `fn` throws on every matching message, the promise rejects once `timeout` is reached.
221226
*/
222-
/**
223-
* @overload
224-
* @param {Function} fn - The function to call with the telemetry message of type `requestType`.
225-
* @param {string} requestType - The request type to assert.
226-
* @param {number} [timeout=30_000] - The timeout in milliseconds.
227-
* @param {number} [expectedMessageCount=1] - The number of messages to expect.
228-
* @returns {Promise<void>} A promise that resolves when the telemetry message of type `requestType` is received and
229-
* the function `fn` has finished running. If `fn` throws an error, the promise will be rejected once `timeout`
230-
* is reached.
231-
*/
232-
assertTelemetryReceived (fn, requestType, timeout = 30_000, expectedMessageCount = 1, resolveAtFirstSuccess = false) {
233-
if (typeof fn !== 'function') {
234-
expectedMessageCount = timeout
235-
timeout = requestType
236-
requestType = fn
237-
fn = noop
238-
}
239-
227+
assertTelemetryReceived ({
228+
fn = noop,
229+
requestType,
230+
timeout = 30_000,
231+
expectedMessageCount = 1,
232+
resolveAtFirstSuccess = false,
233+
namespace,
234+
}) {
240235
let resultResolve
241236
let resultReject
242237
let msgCount = 0
@@ -260,6 +255,7 @@ module.exports = class FakeAgent extends EventEmitter {
260255

261256
const messageHandler = msg => {
262257
if (msg.payload.request_type !== requestType) return
258+
if (namespace !== undefined && msg.payload.payload?.namespace !== namespace) return
263259
msgCount += 1
264260
try {
265261
fn(msg)

integration-tests/opentelemetry.spec.js

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ const { FakeAgent, sandboxCwd, useSandbox, stopProc } = require('./helpers')
99

1010
async function check (agent, proc, timeout, onMessage = () => { }, isMetrics) {
1111
const messageReceiver = isMetrics
12-
? agent.assertTelemetryReceived(onMessage, 'generate-metrics', timeout)
12+
? agent.assertTelemetryReceived({ fn: onMessage, requestType: 'generate-metrics', timeout })
1313
: agent.assertMessageReceived(onMessage, timeout)
1414

1515
const [res] = await Promise.all([

integration-tests/profiler/profiler.spec.js

Lines changed: 63 additions & 44 deletions
Original file line numberDiff line numberDiff line change
@@ -579,9 +579,14 @@ describe('profiler', () => {
579579
DD_PROFILING_ENABLED: '1',
580580
},
581581
})
582-
const checkTelemetry = agent.assertTelemetryReceived('generate-metrics', 1000)
583582
// SSI telemetry is not supposed to have been emitted when DD_INJECTION_ENABLED is absent,
584-
// so expect telemetry callback to time out
583+
// so expect telemetry callback to time out. expectedMessageCount: Infinity keeps the listener
584+
// from ever resolving, so the only outcome is the timeout that expectTimeout requires.
585+
const checkTelemetry = agent.assertTelemetryReceived({
586+
requestType: 'generate-metrics',
587+
timeout: 1000,
588+
expectedMessageCount: Infinity,
589+
})
585590
await Promise.all([checkProfiles(agent, proc, timeout), expectTimeout(checkTelemetry)])
586591
})
587592

@@ -703,38 +708,47 @@ describe('profiler', () => {
703708
let requestCount = 0
704709
let pointsCount = 0
705710

706-
const checkMetrics = agent.assertTelemetryReceived(({ _, payload }) => {
707-
const pp = payload.payload
708-
assert.strictEqual(pp.namespace, 'profilers')
709-
const series = pp.series
710-
const requests = series.find(s => s.metric === 'profile_api.requests')
711-
assert.strictEqual(requests.type, 'count')
712-
// There's a race between metrics and on-shutdown profile, so metric
713-
// value will be between 1 and 3
714-
requestCount = requests.points[0][1]
715-
assert.ok(requestCount >= 1)
716-
assert.ok(requestCount <= 3)
717-
718-
const responses = series.find(s => s.metric === 'profile_api.responses')
719-
assert.strictEqual(responses.type, 'count')
720-
assert.deepStrictEqual(responses.tags, ['status_code:200'])
721-
722-
// Same number of requests and responses
723-
assert.strictEqual(responses.points[0][1], requestCount)
724-
}, 'generate-metrics', timeout, 1, true)
725-
726-
const checkDistributions = agent.assertTelemetryReceived(({ _, payload }) => {
727-
const pp = payload.payload
728-
assert.strictEqual(pp.namespace, 'profilers')
729-
const series = pp.series
730-
assert.strictEqual(series.length, 2)
731-
assert.strictEqual(series[0].metric, 'profile_api.bytes')
732-
assert.strictEqual(series[1].metric, 'profile_api.ms')
733-
734-
// Same number of points
735-
pointsCount = series[0].points.length
736-
assert.strictEqual(pointsCount, series[1].points.length)
737-
}, 'distributions', timeout)
711+
const checkMetrics = agent.assertTelemetryReceived({
712+
fn: ({ _, payload }) => {
713+
const pp = payload.payload
714+
const series = pp.series
715+
const requests = series.find(s => s.metric === 'profile_api.requests')
716+
assert.strictEqual(requests.type, 'count')
717+
// There's a race between the periodic uploader and the on-shutdown
718+
// upload, so the count can include up to one extra request.
719+
requestCount = requests.points[0][1]
720+
assert.ok(requestCount >= 1)
721+
assert.ok(requestCount <= 4)
722+
723+
const responses = series.find(s => s.metric === 'profile_api.responses')
724+
assert.strictEqual(responses.type, 'count')
725+
assert.deepStrictEqual(responses.tags, ['status_code:200'])
726+
727+
// Same number of requests and responses
728+
assert.strictEqual(responses.points[0][1], requestCount)
729+
},
730+
requestType: 'generate-metrics',
731+
timeout,
732+
resolveAtFirstSuccess: true,
733+
namespace: 'profilers',
734+
})
735+
736+
const checkDistributions = agent.assertTelemetryReceived({
737+
fn: ({ _, payload }) => {
738+
const pp = payload.payload
739+
const series = pp.series
740+
assert.strictEqual(series.length, 2)
741+
assert.strictEqual(series[0].metric, 'profile_api.bytes')
742+
assert.strictEqual(series[1].metric, 'profile_api.ms')
743+
744+
// Same number of points
745+
pointsCount = series[0].points.length
746+
assert.strictEqual(pointsCount, series[1].points.length)
747+
},
748+
requestType: 'distributions',
749+
timeout,
750+
namespace: 'profilers',
751+
})
738752

739753
await Promise.all([checkProfiles(agent, proc, timeout), checkMetrics, checkDistributions])
740754

@@ -761,16 +775,21 @@ describe('profiler', () => {
761775
},
762776
})
763777

764-
const checkMetrics = agent.assertTelemetryReceived(({ _, payload }) => {
765-
const pp = payload.payload
766-
assert.strictEqual(pp.namespace, 'profilers');
767-
['live', 'used'].forEach(metricName => {
768-
const sampleContexts = pp.series.find(s => s.metric === `wall.async_contexts_${metricName}`)
769-
assert.notStrictEqual(sampleContexts, undefined)
770-
assert.strictEqual(sampleContexts.type, 'gauge')
771-
assert.ok(sampleContexts.points[0][1] >= 1)
772-
})
773-
}, 'generate-metrics', timeout, 1, true)
778+
const checkMetrics = agent.assertTelemetryReceived({
779+
fn: ({ _, payload }) => {
780+
const pp = payload.payload;
781+
['live', 'used'].forEach(metricName => {
782+
const sampleContexts = pp.series.find(s => s.metric === `wall.async_contexts_${metricName}`)
783+
assert.notStrictEqual(sampleContexts, undefined)
784+
assert.strictEqual(sampleContexts.type, 'gauge')
785+
assert.ok(sampleContexts.points[0][1] >= 1)
786+
})
787+
},
788+
requestType: 'generate-metrics',
789+
timeout,
790+
resolveAtFirstSuccess: true,
791+
namespace: 'profilers',
792+
})
774793

775794
await Promise.all([checkProfiles(agent, proc, timeout), checkMetrics])
776795
})

integration-tests/telemetry.spec.js

Lines changed: 30 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -41,36 +41,44 @@ describe('telemetry', () => {
4141
let ddTraceFound = false
4242
let importInTheMiddleFound = false
4343

44-
await agent.assertTelemetryReceived(msg => {
45-
const { payload } = msg
44+
await agent.assertTelemetryReceived({
45+
fn: msg => {
46+
const { payload } = msg
4647

47-
if (payload.request_type === 'app-dependencies-loaded') {
48-
if (payload.payload.dependencies) {
49-
payload.payload.dependencies.forEach(dependency => {
50-
if (dependency.name === 'dd-trace') {
51-
ddTraceFound = true
52-
}
53-
if (dependency.name === 'import-in-the-middle') {
54-
importInTheMiddleFound = true
55-
}
56-
})
48+
if (payload.request_type === 'app-dependencies-loaded') {
49+
if (payload.payload.dependencies) {
50+
payload.payload.dependencies.forEach(dependency => {
51+
if (dependency.name === 'dd-trace') {
52+
ddTraceFound = true
53+
}
54+
if (dependency.name === 'import-in-the-middle') {
55+
importInTheMiddleFound = true
56+
}
57+
})
58+
}
5759
}
58-
}
59-
}, 'app-dependencies-loaded', 5_000, 1)
60+
},
61+
requestType: 'app-dependencies-loaded',
62+
timeout: 5_000,
63+
})
6064

6165
assert.strictEqual(ddTraceFound, true)
6266
assert.strictEqual(importInTheMiddleFound, true)
6367
})
6468

6569
it('Assert configuration chaining data is sent', async () => {
66-
await agent.assertTelemetryReceived(msg => {
67-
const { configuration } = msg.payload.payload
68-
assertObjectContains(configuration, [
69-
{ name: 'DD_LOGS_INJECTION', value: true, origin: 'default' },
70-
{ name: 'DD_LOGS_INJECTION', value: true, origin: 'env_var' },
71-
{ name: 'DD_LOGS_INJECTION', value: false, origin: 'code' },
72-
])
73-
}, 'app-started', 5_000, 1)
70+
await agent.assertTelemetryReceived({
71+
fn: msg => {
72+
const { configuration } = msg.payload.payload
73+
assertObjectContains(configuration, [
74+
{ name: 'DD_LOGS_INJECTION', value: true, origin: 'default' },
75+
{ name: 'DD_LOGS_INJECTION', value: true, origin: 'env_var' },
76+
{ name: 'DD_LOGS_INJECTION', value: false, origin: 'code' },
77+
])
78+
},
79+
requestType: 'app-started',
80+
timeout: 5_000,
81+
})
7482
})
7583
})
7684
})

0 commit comments

Comments
 (0)