feat(telemetry): metrics with missing fields are warned in the logs. (aws#7196)

## Problem
A metric was forwarded from Flare with missing fields. This resulted in
some confusion about why the metric wasn't showing up properly in
Kibana.

## Solution
- refactor validation to check for missingFields and log a warning. 
- Ideally, we would throw in CI for these, but there is currently a
significant number of metrics emitted without required fields.
- add tests for this validation. 


## Future Work
- Fix existing cases of emitting with missing required fields, so we can
throw in CI when this happens.


---

- Treat all work as PUBLIC. Private `feature/x` branches will not be
squash-merged at release time.
- Your code changes must meet the guidelines in
[CONTRIBUTING.md](https://github.com/aws/aws-toolkit-vscode/blob/master/CONTRIBUTING.md#guidelines).
- License: I confirm that my contribution is made under the terms of the
Apache 2.0 license.

Author: Hweinstock

packages/core/src/shared/logger/logger.ts

@@ -20,6 +20,7 @@ export type LogTopic =
     | 'unknown'
     | 'nextEditPrediction'
     | 'resourceCache'
+    | 'telemetry'
 
 class ErrorLog {
     constructor(

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<EnvType> {
 
 /**
  * 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.
  */

packages/core/src/shared/utilities/collectionUtils.ts

@@ -580,25 +580,25 @@ export function isPresent<T>(value: T | undefined): value is T {
     return value !== undefined
 }
 
-export class CircularBuffer {
-    private buffer = new Set<number>()
+export class CircularBuffer<T> {
+    private buffer = new Set<T>()
     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)
     }
 

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<T, U extends any[], K extends string = string>(
         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<T, U extends any[]>(
+    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
+    }
+}

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<number, ChildProcess> = new Map<number, ChildProcess>()
     #pids: PollingSet<number>
 
@@ -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()

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')
+    })
+})