diff --git a/packages/core/src/shared/logger/logger.ts b/packages/core/src/shared/logger/logger.ts index 38ff40627c1..b398ff93162 100644 --- a/packages/core/src/shared/logger/logger.ts +++ b/packages/core/src/shared/logger/logger.ts @@ -20,6 +20,7 @@ export type LogTopic = | 'unknown' | 'nextEditPrediction' | '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..4d136bc96f0 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, @@ -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,35 +312,51 @@ 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 = getTelemetryLogger() + const logOrThrow = (msg: string, includeSuffix: boolean) => { + const fullMsg = msgPrefix + msg + (includeSuffix ? preferRunSuffix : '') + logger.warn(fullMsg) if (fatal) { - throw new Error(msg) + throw new Error('telemetry: ' + 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) + } + + // 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) { + const logMsg = `${msgPrefix} "${metricName}" emitted with missing fields: ${metadata.missingFields}` + logWarningOnce(logMsg) } } +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..cbf89340ade 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,43 @@ 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 key A function that returns a unique string for each argument set, defaults to joining with ":" seperating + * @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, + options?: { key?: (...args: U) => string; overflow?: number } +): (...args: U) => T | undefined { + const seen = new CircularBuffer(options?.overflow ?? 1000) + const keyMap = options?.key ?? ((...args: U) => args.map(String).join(':')) + + return (...args) => { + const signature = keyMap(...args) + + 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 be44ba89bd2..c24b445cab4 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -8,7 +8,7 @@ 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 { /** Reports an error parsed from the stdin/stdout streams. */ @@ -81,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 @@ -137,12 +136,12 @@ export class ChildProcessTracker { } } - public static logOnce(pid: number, msg: string) { - if (!ChildProcessTracker.loggedPids.contains(pid)) { - ChildProcessTracker.loggedPids.add(pid) + public static logOnce = oncePerUniqueArg( + (_pid: number, msg: string) => { ChildProcessTracker.logger.warn(msg) - } - } + }, + { key: (pid, _) => `${pid}` } + ) public add(childProcess: ChildProcess) { const pid = childProcess.pid() diff --git a/packages/core/src/test/shared/telemetry/util.test.ts b/packages/core/src/test/shared/telemetry/util.test.ts index 27cfcb6b4f7..8d6f3ddc53f 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,110 @@ 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('does not fail validation for metrics with missing fields with 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') + }) +}) diff --git a/packages/core/src/test/shared/utilities/functionUtils.test.ts b/packages/core/src/test/shared/utilities/functionUtils.test.ts index 43da4ebb619..7880d11ff63 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,82 @@ 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}` + }) + + const result1 = fn('hello') + assert.strictEqual(result1, 'processed-hello') + assert.strictEqual(counter, 1, 'First call with unique arg should execute') + + const result2 = fn('hello') + assert.strictEqual(result2, undefined) + assert.strictEqual(counter, 1, 'Second call with same arg should not execute') + + const result3 = fn('world') + assert.strictEqual(result3, 'processed-world') + assert.strictEqual(counter, 2, 'Call with new arg should execute') + + fn('hello') + fn('world') + assert.strictEqual(counter, 2, 'Repeated calls with seen args should not execute') + + // New arg should execute + const result4 = fn('test') + assert.strictEqual(result4, 'processed-test') + assert.strictEqual(counter, 3) + }) + + it('oncePerUniqueArg() with custom key', function () { + let counter = 0 + const fn = oncePerUniqueArg( + (_s1: string, _s2: string) => { + counter++ + }, + { key: (s1, _s2) => s1 } + ) + + fn('hello', 'world') + assert.strictEqual(counter, 1, 'First call with unique arg should execute') + + fn('hello', 'worldss') + assert.strictEqual(counter, 1, 'Second arg being different should not execute') + + fn('world', 'hello') + assert.strictEqual(counter, 2, 'First arg being different should execute') + }) + + it('oncePerUniqueArg() with overflow limit', function () { + let counter = 0 + // Create function with small overflow limit + const fn = oncePerUniqueArg( + (_s: string) => { + counter++ + return counter + }, + { overflow: 2 } + ) + + // Fill the buffer + fn('one') + fn('two') + assert.strictEqual(counter, 2) + + fn('three') + assert.strictEqual(counter, 3, '"three" call should execute since it is a new value') + + // '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 () { 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')