From b30db522d686cfd55105623563c369576d445a3f Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 29 Apr 2025 10:54:34 -0400 Subject: [PATCH 1/8] feat: add validation for missing fields in telemetry --- packages/core/src/shared/logger/logger.ts | 1 + packages/core/src/shared/telemetry/util.ts | 48 ++++--- .../src/test/shared/telemetry/util.test.ts | 124 ++++++++++++++++++ 3 files changed, 153 insertions(+), 20 deletions(-) diff --git a/packages/core/src/shared/logger/logger.ts b/packages/core/src/shared/logger/logger.ts index 85df7b4e1f8..c42ae6e255f 100644 --- a/packages/core/src/shared/logger/logger.ts +++ b/packages/core/src/shared/logger/logger.ts @@ -19,6 +19,7 @@ export type LogTopic = | 'stepfunctions' | 'unknown' | 'resourceCache' + | 'telemetry' class ErrorLog { constructor( diff --git a/packages/core/src/shared/telemetry/util.ts b/packages/core/src/shared/telemetry/util.ts index 34dd7c9eeac..566d409c478 100644 --- a/packages/core/src/shared/telemetry/util.ts +++ b/packages/core/src/shared/telemetry/util.ts @@ -19,7 +19,7 @@ import { } from '../vscode/env' import { addTypeName } from '../utilities/typeConstructors' import globals, { isWeb } from '../extensionGlobals' -import { mapMetadata } from './telemetryLogger' +import { mapMetadata, MetadataObj } from './telemetryLogger' import { Result } from './telemetry.gen' import { MetricDatum } from './clienttelemetry' import { isValidationExemptMetric } from './exemptMetrics' @@ -312,32 +312,40 @@ export async function getComputeEnvType(): Promise { /** * Validates that emitted telemetry metrics - * 1. contain a result property and + * 1. contain a result property * 2. contain a reason propery if result = 'Failed'. + * 3. are not missing fields */ -export function validateMetricEvent(event: MetricDatum, fatal: boolean) { +export function validateMetricEvent(event: MetricDatum, fatal: boolean, isExempt = isValidationExemptMetric) { + if (!isExempt(event.MetricName) && event.Metadata) { + const metadata = mapMetadata([])(event.Metadata) + validateMetadata(event.MetricName, metadata, fatal) + } +} + +function validateMetadata(metricName: string, metadata: MetadataObj, fatal: boolean) { const failedStr: Result = 'Failed' - const telemetryRunDocsStr = + const preferRunSuffix = ' Consider using `.run()` instead of `.emit()`, which will set these properties automatically. ' + 'See https://github.com/aws/aws-toolkit-vscode/blob/master/docs/telemetry.md#guidelines' - - if (!isValidationExemptMetric(event.MetricName) && event.Metadata) { - const metadata = mapMetadata([])(event.Metadata) - let msg = 'telemetry: invalid Metric: ' - - if (metadata.result === undefined) { - msg += `"${event.MetricName}" emitted without the \`result\` property, which is always required.` - } else if (metadata.result === failedStr && metadata.reason === undefined) { - msg += `"${event.MetricName}" emitted with result=Failed but without the \`reason\` property.` - } else { - return // Validation passed. - } - - msg += telemetryRunDocsStr + const msgPrefix = 'invalid Metric: ' + const logger = getLogger('telemetry') + const logOrThrow = (msg: string, includeSuffix: boolean) => { + const fullMsg = msgPrefix + msg + (includeSuffix ? preferRunSuffix : '') + logger.warn(fullMsg) if (fatal) { - throw new Error(msg) + throw new Error(fullMsg) } - getLogger().warn(msg) + } + + if (metadata.result === undefined) { + logOrThrow(`"${metricName}" emitted without the \`result\` property, which is always required.`, true) + } else if (metadata.result === failedStr && metadata.reason === undefined) { + logOrThrow(`"${metricName}" emitted with result=Failed but without the \`reason\` property.`, true) + } + + if (metadata.missingFields) { + logOrThrow(`"${metricName} emitted with missing fields: ${metadata.missingFields}`, false) } } diff --git a/packages/core/src/test/shared/telemetry/util.test.ts b/packages/core/src/test/shared/telemetry/util.test.ts index 27cfcb6b4f7..690e42b372f 100644 --- a/packages/core/src/test/shared/telemetry/util.test.ts +++ b/packages/core/src/test/shared/telemetry/util.test.ts @@ -15,12 +15,15 @@ import { SessionId, telemetryClientIdEnvKey, TelemetryConfig, + validateMetricEvent, } from '../../../shared/telemetry/util' import { extensionVersion } from '../../../shared/vscode/env' import { FakeMemento } from '../../fakeExtensionContext' import { GlobalState } from '../../../shared/globalState' import { randomUUID } from 'crypto' import { isUuid } from '../../../shared/crypto' +import { MetricDatum } from '../../../shared/telemetry/clienttelemetry' +import { assertLogsContain } from '../../globalSetup.test' describe('TelemetryConfig', function () { const settingKey = 'aws.telemetry' @@ -281,3 +284,124 @@ describe('getUserAgent', function () { assert.strictEqual(beforeClient, platformPair()) }) }) + +describe('validateMetricEvent', function () { + it('does not validate exempt metrics', function () { + const metricEvent: MetricDatum = { + MetricName: 'exempt_metric', + Value: 1, + Unit: 'None', + Metadata: [{ Key: 'result', Value: 'Succeeded' }], + } as MetricDatum + + validateMetricEvent(metricEvent, true, (_) => true) + assert.throws(() => assertLogsContain('invalid Metric', false, 'warn')) + }) + + it('passes validation for metrics with proper result property', function () { + const metricEvent: MetricDatum = { + MetricName: 'valid_metric', + Value: 1, + Unit: 'None', + Metadata: [{ Key: 'result', Value: 'Succeeded' }], + } as MetricDatum + + validateMetricEvent(metricEvent, true, (_) => false) + assert.throws(() => assertLogsContain('invalid Metric', false, 'warn')) + }) + + it('passes validation for metrics with Failed result and reason property', function () { + const metricEvent: MetricDatum = { + MetricName: 'valid_failed_metric', + Value: 1, + Unit: 'None', + Metadata: [ + { Key: 'result', Value: 'Failed' }, + { Key: 'reason', Value: 'Something went wrong' }, + ], + } as MetricDatum + + validateMetricEvent(metricEvent, true, (_) => false) + }) + + it('fails validation for metrics missing result property when fatal=true', function () { + const metricEvent: MetricDatum = { + MetricName: 'invalid_metric_no_result', + Value: 1, + Unit: 'None', + Metadata: [{ Key: 'someOtherProperty', Value: 'value' }], + } as MetricDatum + + assert.throws( + () => validateMetricEvent(metricEvent, true, (_) => false), + /emitted without the `result` property/ + ) + }) + + it('logs warning for metrics missing result property when fatal=false', function () { + const metricEvent: MetricDatum = { + MetricName: 'invalid_metric_no_result', + Value: 1, + Unit: 'None', + Metadata: [{ Key: 'someOtherProperty', Value: 'value' }], + } as MetricDatum + + validateMetricEvent(metricEvent, false, (_) => false) + assertLogsContain('invalid Metric', false, 'warn') + }) + + it('fails validation for metrics with Failed result but missing reason property when fatal=true', function () { + const metricEvent: MetricDatum = { + MetricName: 'invalid_metric_failed_no_reason', + Value: 1, + Unit: 'None', + Metadata: [{ Key: 'result', Value: 'Failed' }], + } as MetricDatum + + assert.throws( + () => validateMetricEvent(metricEvent, true), + /emitted with result=Failed but without the `reason` property/ + ) + }) + + it('logs warning for metrics with Failed result but missing reason property when fatal=false', function () { + const metricEvent: MetricDatum = { + MetricName: 'invalid_metric_failed_no_reason', + Value: 1, + Unit: 'None', + Metadata: [{ Key: 'result', Value: 'Failed' }], + } as MetricDatum + + validateMetricEvent(metricEvent, false) + assertLogsContain('invalid Metric', false, 'warn') + }) + + it('fails validation for metrics with missing fields when fatal=true', function () { + const metricEvent: MetricDatum = { + MetricName: 'invalid_metric_missing_fields', + Value: 1, + Unit: 'None', + Metadata: [ + { Key: 'result', Value: 'Succeeded' }, + { Key: 'missingFields', Value: 'field1,field2' }, + ], + } as MetricDatum + + assert.throws(() => validateMetricEvent(metricEvent, true), /emitted with missing fields/) + }) + + it('logs warning for metrics with missing fields when fatal=false', function () { + const metricEvent: MetricDatum = { + MetricName: 'invalid_metric_missing_fields', + Value: 1, + Unit: 'None', + Metadata: [ + { Key: 'result', Value: 'Succeeded' }, + { Key: 'missingFields', Value: 'field1,field2' }, + ], + } as MetricDatum + + validateMetricEvent(metricEvent, false) + assertLogsContain('invalid Metric', false, 'warn') + }) +}) From 1b3cfc4ddfd16e0d484fce609b004f6f1f31192c Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 29 Apr 2025 16:35:53 -0400 Subject: [PATCH 2/8] feat: avoid throwing on missingFields --- packages/core/src/shared/telemetry/util.ts | 3 ++- packages/core/src/test/shared/telemetry/util.test.ts | 5 +++-- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/packages/core/src/shared/telemetry/util.ts b/packages/core/src/shared/telemetry/util.ts index 566d409c478..e5e4c5aa631 100644 --- a/packages/core/src/shared/telemetry/util.ts +++ b/packages/core/src/shared/telemetry/util.ts @@ -344,8 +344,9 @@ function validateMetadata(metricName: string, metadata: MetadataObj, fatal: bool logOrThrow(`"${metricName}" emitted with result=Failed but without the \`reason\` property.`, true) } + // TODO: there are many instances in the toolkit where we emit metrics with missing fields. If those can be removed, we can configure this to throw in CI. if (metadata.missingFields) { - logOrThrow(`"${metricName} emitted with missing fields: ${metadata.missingFields}`, false) + logger.warn(msgPrefix + `"${metricName} emitted with missing fields: ${metadata.missingFields}`, false) } } diff --git a/packages/core/src/test/shared/telemetry/util.test.ts b/packages/core/src/test/shared/telemetry/util.test.ts index 690e42b372f..879e81cee15 100644 --- a/packages/core/src/test/shared/telemetry/util.test.ts +++ b/packages/core/src/test/shared/telemetry/util.test.ts @@ -376,7 +376,7 @@ describe('validateMetricEvent', function () { assertLogsContain('invalid Metric', false, 'warn') }) - it('fails validation for metrics with missing fields when fatal=true', function () { + it('does not fail validation for metrics with missing fields when fatal=true', function () { const metricEvent: MetricDatum = { MetricName: 'invalid_metric_missing_fields', Value: 1, @@ -387,7 +387,8 @@ describe('validateMetricEvent', function () { ], } as MetricDatum - assert.throws(() => validateMetricEvent(metricEvent, true), /emitted with missing fields/) + validateMetricEvent(metricEvent, false) + assertLogsContain('invalid Metric', false, 'warn') }) it('logs warning for metrics with missing fields when fatal=false', function () { From 8f4fb641f4d0180a0403a664a59d972b1f04374c Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 29 Apr 2025 16:46:19 -0400 Subject: [PATCH 3/8] test: remove duplicate test --- .../core/src/test/shared/telemetry/util.test.ts | 17 +---------------- 1 file changed, 1 insertion(+), 16 deletions(-) diff --git a/packages/core/src/test/shared/telemetry/util.test.ts b/packages/core/src/test/shared/telemetry/util.test.ts index 879e81cee15..8d6f3ddc53f 100644 --- a/packages/core/src/test/shared/telemetry/util.test.ts +++ b/packages/core/src/test/shared/telemetry/util.test.ts @@ -376,22 +376,7 @@ describe('validateMetricEvent', function () { assertLogsContain('invalid Metric', false, 'warn') }) - it('does not fail validation for metrics with missing fields when fatal=true', function () { - const metricEvent: MetricDatum = { - MetricName: 'invalid_metric_missing_fields', - Value: 1, - Unit: 'None', - Metadata: [ - { Key: 'result', Value: 'Succeeded' }, - { Key: 'missingFields', Value: 'field1,field2' }, - ], - } as MetricDatum - - validateMetricEvent(metricEvent, false) - assertLogsContain('invalid Metric', false, 'warn') - }) - - it('logs warning for metrics with missing fields when fatal=false', function () { + it('does not fail validation for metrics with missing fields with fatal=true', function () { const metricEvent: MetricDatum = { MetricName: 'invalid_metric_missing_fields', Value: 1, From 2f91e4a0fa4f6fa7006119a79ccd11c6fd4b4914 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 29 Apr 2025 17:04:57 -0400 Subject: [PATCH 4/8] test: update test with new error message --- .../core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts b/packages/core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts index 2a0fcaa0e0d..3ab9a22346a 100644 --- a/packages/core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts +++ b/packages/core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts @@ -152,7 +152,7 @@ describe('RemoteInvokeWebview', () => { assert.ok(err instanceof Error) assert.strictEqual( err.message, - 'telemetry: invalid Metric: "lambda_invokeRemote" emitted with result=Failed but without the `reason` property. Consider using `.run()` instead of `.emit()`, which will set these properties automatically. See https://github.com/aws/aws-toolkit-vscode/blob/master/docs/telemetry.md#guidelines' + 'invalid Metric: "lambda_invokeRemote" emitted with result=Failed but without the `reason` property. Consider using `.run()` instead of `.emit()`, which will set these properties automatically. See https://github.com/aws/aws-toolkit-vscode/blob/master/docs/telemetry.md#guidelines' ) } From b092ab12617f31693d73720a86d049cc7ca698f2 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 29 Apr 2025 17:29:52 -0400 Subject: [PATCH 5/8] test: swap test case back --- packages/core/src/shared/telemetry/util.ts | 2 +- .../core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/core/src/shared/telemetry/util.ts b/packages/core/src/shared/telemetry/util.ts index e5e4c5aa631..208fcdb66d3 100644 --- a/packages/core/src/shared/telemetry/util.ts +++ b/packages/core/src/shared/telemetry/util.ts @@ -334,7 +334,7 @@ function validateMetadata(metricName: string, metadata: MetadataObj, fatal: bool const fullMsg = msgPrefix + msg + (includeSuffix ? preferRunSuffix : '') logger.warn(fullMsg) if (fatal) { - throw new Error(fullMsg) + throw new Error('telemetry: ' + fullMsg) } } diff --git a/packages/core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts b/packages/core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts index 3ab9a22346a..2a0fcaa0e0d 100644 --- a/packages/core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts +++ b/packages/core/src/test/lambda/vue/remoteInvoke/invokeLambda.test.ts @@ -152,7 +152,7 @@ describe('RemoteInvokeWebview', () => { assert.ok(err instanceof Error) assert.strictEqual( err.message, - 'invalid Metric: "lambda_invokeRemote" emitted with result=Failed but without the `reason` property. Consider using `.run()` instead of `.emit()`, which will set these properties automatically. See https://github.com/aws/aws-toolkit-vscode/blob/master/docs/telemetry.md#guidelines' + 'telemetry: invalid Metric: "lambda_invokeRemote" emitted with result=Failed but without the `reason` property. Consider using `.run()` instead of `.emit()`, which will set these properties automatically. See https://github.com/aws/aws-toolkit-vscode/blob/master/docs/telemetry.md#guidelines' ) } From 095ed5e24df325d3a1c7793848c6bc13b420e6e3 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 7 May 2025 09:49:00 -0400 Subject: [PATCH 6/8] feat: only log each warning message once for invalid metrics --- packages/core/src/shared/telemetry/util.ts | 12 +++- .../src/shared/utilities/collectionUtils.ts | 10 +-- .../src/shared/utilities/functionUtils.ts | 39 ++++++++++++ .../core/src/shared/utilities/processUtils.ts | 2 +- .../shared/utilities/functionUtils.test.ts | 61 ++++++++++++++++++- 5 files changed, 114 insertions(+), 10 deletions(-) diff --git a/packages/core/src/shared/telemetry/util.ts b/packages/core/src/shared/telemetry/util.ts index 208fcdb66d3..d009a596701 100644 --- a/packages/core/src/shared/telemetry/util.ts +++ b/packages/core/src/shared/telemetry/util.ts @@ -8,7 +8,7 @@ import { env, version } from 'vscode' import * as os from 'os' import { getLogger } from '../logger/logger' import { fromExtensionManifest, Settings } from '../settings' -import { memoize, once } from '../utilities/functionUtils' +import { memoize, once, oncePerUniqueArg } from '../utilities/functionUtils' import { isInDevEnv, extensionVersion, @@ -329,7 +329,7 @@ function validateMetadata(metricName: string, metadata: MetadataObj, fatal: bool ' Consider using `.run()` instead of `.emit()`, which will set these properties automatically. ' + 'See https://github.com/aws/aws-toolkit-vscode/blob/master/docs/telemetry.md#guidelines' const msgPrefix = 'invalid Metric: ' - const logger = getLogger('telemetry') + const logger = getTelemetryLogger() const logOrThrow = (msg: string, includeSuffix: boolean) => { const fullMsg = msgPrefix + msg + (includeSuffix ? preferRunSuffix : '') logger.warn(fullMsg) @@ -346,10 +346,16 @@ function validateMetadata(metricName: string, metadata: MetadataObj, fatal: bool // TODO: there are many instances in the toolkit where we emit metrics with missing fields. If those can be removed, we can configure this to throw in CI. if (metadata.missingFields) { - logger.warn(msgPrefix + `"${metricName} emitted with missing fields: ${metadata.missingFields}`, false) + logWarningOnce(`"${metricName}" emitted with missing fields: ${metadata.missingFields}`) } } +function getTelemetryLogger() { + return getLogger('telemetry') +} + +const logWarningOnce = oncePerUniqueArg((m: string) => getTelemetryLogger().warn(m)) + /** * Potentially helpful values for the 'source' field in telemetry. */ diff --git a/packages/core/src/shared/utilities/collectionUtils.ts b/packages/core/src/shared/utilities/collectionUtils.ts index 8a428b8e8b7..a5a5e83e7d6 100644 --- a/packages/core/src/shared/utilities/collectionUtils.ts +++ b/packages/core/src/shared/utilities/collectionUtils.ts @@ -580,25 +580,25 @@ export function isPresent(value: T | undefined): value is T { return value !== undefined } -export class CircularBuffer { - private buffer = new Set() +export class CircularBuffer { + private buffer = new Set() private maxSize: number constructor(size: number) { this.maxSize = size } - add(value: number): void { + add(value: T): void { if (this.buffer.size >= this.maxSize) { // Set iterates its keys in insertion-order. // https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Set const firstKey = this.buffer.keys().next().value - this.buffer.delete(firstKey) + this.buffer.delete(firstKey as T) } this.buffer.add(value) } - contains(value: number): boolean { + contains(value: T): boolean { return this.buffer.has(value) } diff --git a/packages/core/src/shared/utilities/functionUtils.ts b/packages/core/src/shared/utilities/functionUtils.ts index 3bcb87730fa..4f530005358 100644 --- a/packages/core/src/shared/utilities/functionUtils.ts +++ b/packages/core/src/shared/utilities/functionUtils.ts @@ -3,6 +3,7 @@ * SPDX-License-Identifier: Apache-2.0 */ +import { CircularBuffer } from './collectionUtils' import { Timeout } from './timeoutUtils' /** @@ -156,3 +157,41 @@ export function keyedDebounce( return promise } } +/** + * Creates a function that runs only for unique arguments that haven't been seen before. + * + * This utility tracks all unique inputs it has seen and only executes the callback + * for new inputs. Unlike `onceChanged` which only compares with the previous invocation, + * this function maintains a history of all arguments it has processed. + * + * @param fn The function to execute for unique arguments + * @param overflow The maximum number of unique arguments to store. + * @returns A wrapped function that only executes for new unique arguments + * + * @example + * ```ts + * const logOnce = oncePerUniqueArg((message) => console.log(message)) + * + * logOnce('hello') // prints: hello + * logOnce('world') // prints: world + * logOnce('hello') // nothing happens (already seen) + * logOnce('test') // prints: test + * ``` + */ +export function oncePerUniqueArg( + fn: (...args: U) => T, + overflow?: number +): (...args: U) => T | undefined { + const seen = new CircularBuffer(overflow ?? 1000) + + return (...args) => { + const signature = args.map(String).join(':') + + if (!seen.contains(signature)) { + seen.add(signature) + return fn(...args) + } + + return undefined + } +} diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 0204736f500..0e9096fc334 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -74,7 +74,7 @@ export class ChildProcessTracker { cpu: 50, } static readonly logger = logger.getLogger('childProcess') - static readonly loggedPids = new CircularBuffer(1000) + static readonly loggedPids = new CircularBuffer(1000) #processByPid: Map = new Map() #pids: PollingSet diff --git a/packages/core/src/test/shared/utilities/functionUtils.test.ts b/packages/core/src/test/shared/utilities/functionUtils.test.ts index 43da4ebb619..f4a8d174e24 100644 --- a/packages/core/src/test/shared/utilities/functionUtils.test.ts +++ b/packages/core/src/test/shared/utilities/functionUtils.test.ts @@ -4,7 +4,7 @@ */ import assert from 'assert' -import { once, onceChanged, debounce } from '../../../shared/utilities/functionUtils' +import { once, onceChanged, debounce, oncePerUniqueArg } from '../../../shared/utilities/functionUtils' import { installFakeClock } from '../../testUtil' describe('functionUtils', function () { @@ -48,6 +48,65 @@ describe('functionUtils', function () { fn('arg1', arg2_) assert.strictEqual(counter, 3) }) + + it('oncePerUniqueArg()', function () { + let counter = 0 + const fn = oncePerUniqueArg((s: string) => { + counter++ + return `processed-${s}` + }) + + // First call with unique arg should execute + const result1 = fn('hello') + assert.strictEqual(result1, 'processed-hello') + assert.strictEqual(counter, 1) + + // Second call with same arg should not execute + const result2 = fn('hello') + assert.strictEqual(result2, undefined) + assert.strictEqual(counter, 1) + + // Call with new arg should execute + const result3 = fn('world') + assert.strictEqual(result3, 'processed-world') + assert.strictEqual(counter, 2) + + // Repeated calls with seen args should not execute + fn('hello') + fn('world') + assert.strictEqual(counter, 2) + + // New arg should execute + const result4 = fn('test') + assert.strictEqual(result4, 'processed-test') + assert.strictEqual(counter, 3) + }) + + it('oncePerUniqueArg() with overflow limit', function () { + let counter = 0 + // Create function with small overflow limit + const fn = oncePerUniqueArg((s: string) => { + counter++ + return counter + }, 2) + + // Fill the buffer + fn('one') + fn('two') + assert.strictEqual(counter, 2) + + // This should execute since it's a new value + fn('three') + assert.strictEqual(counter, 3) + + // 'one' should now be treated as new again since it was evicted + fn('one') + assert.strictEqual(counter, 4, 'one should still be in the buffer') + + // 'three' should still be in the buffer (not executed) + fn('three') + assert.strictEqual(counter, 4, 'three should still be in the buffer') + }) }) describe('debounce', function () { From f27bacbfcd92811346a4eedbb574de5be5644349 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 7 May 2025 10:01:58 -0400 Subject: [PATCH 7/8] refactor: process utils uses new utility --- .../core/src/shared/utilities/processUtils.ts | 27 +++++++++++-------- 1 file changed, 16 insertions(+), 11 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 0e9096fc334..973bf65cb17 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -9,6 +9,7 @@ import * as logger from '../logger/logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { CircularBuffer } from './collectionUtils' +import { oncePerUniqueArg } from './functionUtils' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -74,7 +75,6 @@ export class ChildProcessTracker { cpu: 50, } static readonly logger = logger.getLogger('childProcess') - static readonly loggedPids = new CircularBuffer(1000) #processByPid: Map = new Map() #pids: PollingSet @@ -102,27 +102,32 @@ export class ChildProcessTracker { private async checkProcessUsage(pid: number): Promise { if (!this.#pids.has(pid)) { - ChildProcessTracker.logOnce(pid, `Missing process with id ${pid}`) + ChildProcessTracker.logMissingPid(pid) return } const stats = this.getUsage(pid) if (stats) { ChildProcessTracker.logger.debug(`Process ${pid} usage: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { - ChildProcessTracker.logOnce(pid, `Process ${pid} exceeded memory threshold: ${stats.memory}`) + ChildProcessTracker.logExceededThreshold(pid, 'memory') } if (stats.cpu > ChildProcessTracker.thresholds.cpu) { - ChildProcessTracker.logOnce(pid, `Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + ChildProcessTracker.logExceededThreshold(pid, 'cpu') } } } - public static logOnce(pid: number, msg: string) { - if (!ChildProcessTracker.loggedPids.contains(pid)) { - ChildProcessTracker.loggedPids.add(pid) - ChildProcessTracker.logger.warn(msg) - } - } + private static logMissingPid = oncePerUniqueArg((pid: number) => + ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) + ) + + private static logStatFailure = oncePerUniqueArg((pid: number, e: unknown) => + ChildProcessTracker.logger.warn(`Failed to get process stats for ${pid}: ${e}`) + ) + + private static logExceededThreshold = oncePerUniqueArg((pid: number, threshold: keyof ProcessStats) => + ChildProcessTracker.logger.warn(`Process ${pid} exceeded ${threshold} threshold`) + ) public add(childProcess: ChildProcess) { const pid = childProcess.pid() @@ -156,7 +161,7 @@ export class ChildProcessTracker { // isWin() leads to circular dependency. return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() } catch (e) { - ChildProcessTracker.logOnce(pid, `Failed to get process stats for ${pid}: ${e}`) + ChildProcessTracker.logStatFailure(pid, e) return { cpu: 0, memory: 0 } } From fd91f2a430f1b61a2b92ad01bc0f6ba6c48ec384 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 7 May 2025 10:46:41 -0400 Subject: [PATCH 8/8] fix: adjust tests --- packages/core/src/shared/telemetry/util.ts | 3 ++- .../core/src/shared/utilities/processUtils.ts | 2 -- .../shared/utilities/processUtils.test.ts | 23 +++++++++++-------- 3 files changed, 15 insertions(+), 13 deletions(-) diff --git a/packages/core/src/shared/telemetry/util.ts b/packages/core/src/shared/telemetry/util.ts index d009a596701..4d136bc96f0 100644 --- a/packages/core/src/shared/telemetry/util.ts +++ b/packages/core/src/shared/telemetry/util.ts @@ -346,7 +346,8 @@ function validateMetadata(metricName: string, metadata: MetadataObj, fatal: bool // TODO: there are many instances in the toolkit where we emit metrics with missing fields. If those can be removed, we can configure this to throw in CI. if (metadata.missingFields) { - logWarningOnce(`"${metricName}" emitted with missing fields: ${metadata.missingFields}`) + const logMsg = `${msgPrefix} "${metricName}" emitted with missing fields: ${metadata.missingFields}` + logWarningOnce(logMsg) } } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 011ba83cdbf..c24b445cab4 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -8,7 +8,6 @@ import * as crossSpawn from 'cross-spawn' import * as logger from '../logger/logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' -import { CircularBuffer } from './collectionUtils' import { oncePerUniqueArg } from './functionUtils' export interface RunParameterContext { @@ -82,7 +81,6 @@ export interface ProcessStats { export class ChildProcessTracker { static readonly pollingInterval: number = 10000 // Check usage every 10 seconds static readonly logger = logger.getLogger('childProcess') - static readonly loggedPids = new CircularBuffer(1000) #processByPid: Map = new Map() #pids: PollingSet diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 65817d80a56..fda6d93293e 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -395,10 +395,6 @@ describe('ChildProcessTracker', function () { usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') }) - beforeEach(function () { - ChildProcessTracker.loggedPids.clear() - }) - afterEach(function () { tracker.clear() usageMock.reset() @@ -451,7 +447,7 @@ describe('ChildProcessTracker', function () { assert.strictEqual(tracker.size, 0, 'expected tracker to be empty') }) - it('logs a warning message when system usage exceeds threshold', async function () { + it('logs a warning message when cpu usage exceeds threshold', async function () { const runningProcess = startSleepProcess() tracker.add(runningProcess.childProcess) @@ -459,18 +455,25 @@ describe('ChildProcessTracker', function () { cpu: defaultProcessWarnThresholds.cpu + 1, memory: 0, } - const highMemory: ProcessStats = { - cpu: 0, - memory: defaultProcessWarnThresholds.memory + 1, - } usageMock.returns(highCpu) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded cpu threshold', false, 'warn') - ChildProcessTracker.loggedPids.clear() + await stopAndWait(runningProcess) + }) + + it('logs a warning message when memory usage exceeds threshold', async function () { + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) + + const highMemory: ProcessStats = { + cpu: 0, + memory: defaultProcessWarnThresholds.memory + 1, + } usageMock.returns(highMemory) + await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn')