From 601fdf62f37416cf4ee483e4db656e5e1b63c627 Mon Sep 17 00:00:00 2001 From: Satyaki Ghosh Date: Fri, 2 Oct 2026 13:44:39 -0400 Subject: [PATCH 1/3] Fix doubled log prefixes and isolate the telemetry opt-in setting The output channel is a LogOutputChannel, which already stamps the time and level on every line, yet the logger prepended its own and wrote through appendLine, so every line carried two timestamps and two levels and warnings and errors were recorded as info. A concatenation bug also repeated the whole prefix whenever a message accompanied the data. The logger now writes through the channel's own debug/info/warn/error with only the component name, and errors print their stack instead of "{}". Other IDE clients of the language server contribute the identical aws.cloudformation.telemetry.enabled setting, so a choice recorded by one extension switched telemetry on or off for the other. The opt-in setting now lives in this extension's own namespace as aws.iac.telemetry.enabled. The globalState keys are unchanged: VS Code scopes them per extension. Users who answered the 1.0.0 prompt are asked once more, since their choice is stored under the old key. --- README.md | 5 +- package.json | 4 +- src/telemetry/TelemetryOptIn.ts | 7 +- src/utils/Logger.ts | 37 ++---- tst/__mocks__/vscode.ts | 5 + tst/auth/awsCredentials.test.ts | 2 +- .../CfnDevLspServerProvider.test.ts | 2 +- .../CfnRemoteLspServerProvider.test.ts | 4 +- tst/lsp-server/LspLauncher.test.ts | 2 +- tst/lsp-server/LspServerLifecycle.test.ts | 2 +- .../installer/BaseLspInstaller.test.ts | 2 +- .../installer/CfnLspInstaller.test.ts | 2 +- tst/lsp-server/installer/platform.test.ts | 2 +- .../installer/zipExtraction.test.ts | 2 +- tst/telemetry/ClientId.test.ts | 2 +- tst/telemetry/TelemetryOptIn.test.ts | 68 +++++++++++ tst/utils/Logger.test.ts | 107 ++++++++++++++++++ 17 files changed, 212 insertions(+), 43 deletions(-) create mode 100644 tst/telemetry/TelemetryOptIn.test.ts create mode 100644 tst/utils/Logger.test.ts diff --git a/README.md b/README.md index 5aacbd34f..a20c31be7 100644 --- a/README.md +++ b/README.md @@ -90,13 +90,14 @@ template validation, and importing resource state, are not available in this ext | `aws.cloudformation.diagnostics.cfnGuard.enabledRulePacks` | `["cis-aws-benchmark-level-1"]` | Managed rule packs to validate against | | `aws.cloudformation.diagnostics.cfnGuard.rulesFile` | `""` | Path to a custom cfn-guard rules file; empty uses the enabled rule packs | | `aws.cloudformation.trace.server` | `"off"` | Trace communication with the language server (`messages`, `verbose`) | -| `aws.cloudformation.telemetry.enabled` | `false` | Share anonymous usage telemetry with AWS | +| `aws.iac.telemetry.enabled` | `false` | Share anonymous usage telemetry with AWS | | `aws.cloudformation.telemetry.logLevel` | `"info"` | Log level of the extension output channel; applies after a window reload | ## Telemetry Telemetry is off by default. On first activation the extension asks whether to share anonymous usage data with AWS; -you can change the choice at any time with `aws.cloudformation.telemetry.enabled`. See the language server's +you can change the choice at any time with `aws.iac.telemetry.enabled`. The setting is specific to this extension; +it does not read or change the telemetry preference of any other extension. See the language server's [telemetry documentation](https://github.com/aws-cloudformation/cloudformation-languageserver/tree/main/src/telemetry) for what is collected. diff --git a/package.json b/package.json index 098d9323a..2706e09a6 100644 --- a/package.json +++ b/package.json @@ -128,10 +128,10 @@ "default": "off", "description": "Traces the communication between VS Code and the language server" }, - "aws.cloudformation.telemetry.enabled": { + "aws.iac.telemetry.enabled": { "type": "boolean", "default": false, - "description": "Configure anonymous telemetry collection (cannot disable unless it is a production release)" + "description": "Share anonymous usage telemetry from the AWS CloudFormation extension with AWS" }, "aws.cloudformation.telemetry.logLevel": { "type": "string", diff --git a/src/telemetry/TelemetryOptIn.ts b/src/telemetry/TelemetryOptIn.ts index 83896bcbb..dad2ec8d4 100644 --- a/src/telemetry/TelemetryOptIn.ts +++ b/src/telemetry/TelemetryOptIn.ts @@ -15,7 +15,10 @@ const stateKeys = { unpersistedResponse: `${ExtensionConfigKey}.telemetry.unpersistedResponse`, } as const; -const telemetrySettingKey = 'aws.cloudformation.telemetry'; +// Kept outside the `aws.cloudformation.*` namespace: other IDE clients of the language server +// contribute `aws.cloudformation.telemetry.enabled`, and consent given to one extension must not +// switch telemetry on or off for another. +const telemetrySettingKey = 'aws.iac.telemetry'; const thirtyDaysMs = 30 * 24 * 60 * 60 * 1000; const promptTimeoutMs = 2500; const telemetryDocsUrl = 'https://github.com/aws-cloudformation/cloudformation-languageserver/tree/main/src/telemetry'; @@ -105,7 +108,7 @@ async function promptTelemetryOptIn(context: ExtensionContext): Promise const { globalState } = context; const response = await window.showInformationMessage( - 'Help us improve the AWS CloudFormation Language Server by sharing anonymous telemetry data with AWS. You can change this preference at any time in aws.cloudformation Settings.', + 'Help us improve the AWS CloudFormation Language Server by sharing anonymous telemetry data with AWS. You can change this preference at any time with the aws.iac.telemetry.enabled setting.', TelemetryChoice.Allow, TelemetryChoice.Later, TelemetryChoice.Never, diff --git a/src/utils/Logger.ts b/src/utils/Logger.ts index 7e08bc55d..f588168c2 100644 --- a/src/utils/Logger.ts +++ b/src/utils/Logger.ts @@ -1,5 +1,5 @@ -import { OutputChannel, workspace } from 'vscode'; -import { toString } from './Utils'; +import { LogOutputChannel, workspace } from 'vscode'; +import { extractErrorMessage, toString } from './Utils'; type LogLevel = 'debug' | 'info' | 'warn' | 'error'; @@ -10,15 +10,6 @@ const levelPriority: Record = { error: 3, }; -function formatTime(): string { - return new Date().toLocaleTimeString('en-US', { - hour: '2-digit', - minute: '2-digit', - second: '2-digit', - hour12: true, - }); -} - export class Logger { private readonly configuredLevel = workspace .getConfiguration('aws.cloudformation.telemetry') @@ -26,7 +17,7 @@ export class Logger { constructor( private readonly name: string, - private readonly channel: OutputChannel, + private readonly channel: LogOutputChannel, ) {} private shouldLog(level: LogLevel): boolean { @@ -38,15 +29,16 @@ export class Logger { return; } - let line = `[${formatTime()}] ${capitalize(level)}: [${this.name}]`; + // The channel stamps time and level itself; only the component name is added here. + let line = `[${this.name}]`; if (message) { - line += `${line} ${message}`; + line += ` ${message}`; } if (data) { - line += ` ${toString(data)}`; + line += ` ${data instanceof Error ? (data.stack ?? extractErrorMessage(data)) : toString(data)}`; } - this.channel.appendLine(line); + this.channel[level](line); } debug(data: unknown, message?: string): void { @@ -67,10 +59,10 @@ export class Logger { } export class LoggerFactory { - private static channel: OutputChannel; + private static channel: LogOutputChannel; private static readonly loggers = new Map(); - static initialize(channel: OutputChannel) { + static initialize(channel: LogOutputChannel) { this.channel = channel; } @@ -89,14 +81,7 @@ export class LoggerFactory { /** @internal For testing only */ static reset(): void { - this.channel = undefined as unknown as OutputChannel; + this.channel = undefined as unknown as LogOutputChannel; this.loggers.clear(); } } - -function capitalize(str: string) { - return str - .split(' ') - .map((word) => word.charAt(0).toUpperCase() + word.slice(1)) - .join(' '); -} diff --git a/tst/__mocks__/vscode.ts b/tst/__mocks__/vscode.ts index 70ba837b4..adef4e654 100644 --- a/tst/__mocks__/vscode.ts +++ b/tst/__mocks__/vscode.ts @@ -20,6 +20,11 @@ const vscode = { }), createOutputChannel: vi.fn().mockReturnValue({ appendLine: vi.fn(), + trace: vi.fn(), + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), dispose: vi.fn(), }), showQuickPick: vi.fn(), diff --git a/tst/auth/awsCredentials.test.ts b/tst/auth/awsCredentials.test.ts index 04496642e..e3be4e76e 100644 --- a/tst/auth/awsCredentials.test.ts +++ b/tst/auth/awsCredentials.test.ts @@ -21,7 +21,7 @@ describe('AwsCredentialsService', () => { vi.clearAllMocks(); LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); mockStatusBarItem = { show: vi.fn(), diff --git a/tst/lsp-server/CfnDevLspServerProvider.test.ts b/tst/lsp-server/CfnDevLspServerProvider.test.ts index a9d059695..6f9ca762f 100644 --- a/tst/lsp-server/CfnDevLspServerProvider.test.ts +++ b/tst/lsp-server/CfnDevLspServerProvider.test.ts @@ -15,7 +15,7 @@ describe('CfnDevLspServerProvider', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); testDir = nodeFs.mkdtempSync(join(tmpdir(), 'cfn-dev-test-')); }); diff --git a/tst/lsp-server/CfnRemoteLspServerProvider.test.ts b/tst/lsp-server/CfnRemoteLspServerProvider.test.ts index 457a3a026..9a26baeaa 100644 --- a/tst/lsp-server/CfnRemoteLspServerProvider.test.ts +++ b/tst/lsp-server/CfnRemoteLspServerProvider.test.ts @@ -24,7 +24,7 @@ describe('CfnRemoteLspServerProvider', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); testDir = nodeFs.mkdtempSync(join(tmpdir(), 'cfn-remote-provider-test-')); }); @@ -125,7 +125,7 @@ describe('Installer → Provider → Launcher integration: failed managed path i beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); testDir = nodeFs.mkdtempSync(join(tmpdir(), 'cfn-integration-test-')); }); diff --git a/tst/lsp-server/LspLauncher.test.ts b/tst/lsp-server/LspLauncher.test.ts index c7f986637..fe0cbfcf3 100644 --- a/tst/lsp-server/LspLauncher.test.ts +++ b/tst/lsp-server/LspLauncher.test.ts @@ -47,7 +47,7 @@ describe('LspLauncher', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); let resolveCount = 0; resolver = { diff --git a/tst/lsp-server/LspServerLifecycle.test.ts b/tst/lsp-server/LspServerLifecycle.test.ts index 77127ef51..0fb1cd349 100644 --- a/tst/lsp-server/LspServerLifecycle.test.ts +++ b/tst/lsp-server/LspServerLifecycle.test.ts @@ -30,7 +30,7 @@ describe('LspServerLifecycleController', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); let resolveCount = 0; resolveServer = vi.fn(() => Promise.resolve(`server-${++resolveCount}`)); diff --git a/tst/lsp-server/installer/BaseLspInstaller.test.ts b/tst/lsp-server/installer/BaseLspInstaller.test.ts index 558c2f97c..beed9f134 100644 --- a/tst/lsp-server/installer/BaseLspInstaller.test.ts +++ b/tst/lsp-server/installer/BaseLspInstaller.test.ts @@ -267,7 +267,7 @@ describe('BaseLspInstaller', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); memFs = new MemoryFs(); fetcher = new MockFetcher(); installer = createInstaller(baseDir, memFs, fetcher); diff --git a/tst/lsp-server/installer/CfnLspInstaller.test.ts b/tst/lsp-server/installer/CfnLspInstaller.test.ts index c42666b7a..ceb908d9e 100644 --- a/tst/lsp-server/installer/CfnLspInstaller.test.ts +++ b/tst/lsp-server/installer/CfnLspInstaller.test.ts @@ -28,7 +28,7 @@ describe('CfnLspInstaller', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); testDir = nodeFs.mkdtempSync(join(tmpdir(), 'cfn-installer-test-')); installer = new CfnLspInstaller(testDir, 'prod', undefined, undefined, async () => {}); }); diff --git a/tst/lsp-server/installer/platform.test.ts b/tst/lsp-server/installer/platform.test.ts index 7d1907059..c3dbb3402 100644 --- a/tst/lsp-server/installer/platform.test.ts +++ b/tst/lsp-server/installer/platform.test.ts @@ -13,7 +13,7 @@ vi.mock('vscode'); describe('platform detection', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); }); describe('detectPlatformTarget (default, no injection)', () => { diff --git a/tst/lsp-server/installer/zipExtraction.test.ts b/tst/lsp-server/installer/zipExtraction.test.ts index 5b58f9a22..95d44592f 100644 --- a/tst/lsp-server/installer/zipExtraction.test.ts +++ b/tst/lsp-server/installer/zipExtraction.test.ts @@ -120,7 +120,7 @@ describe('BaseLspInstaller - zip extraction', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); testDir = nodeFs.mkdtempSync(join(tmpdir(), 'zip-test-')); }); diff --git a/tst/telemetry/ClientId.test.ts b/tst/telemetry/ClientId.test.ts index 745812cc6..3fbbbf9dc 100644 --- a/tst/telemetry/ClientId.test.ts +++ b/tst/telemetry/ClientId.test.ts @@ -14,7 +14,7 @@ describe('ClientId / telemetry', () => { beforeEach(() => { LoggerFactory.reset(); - LoggerFactory.initialize(window.createOutputChannel('test')); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); const data: Record = {}; mockState = { data, diff --git a/tst/telemetry/TelemetryOptIn.test.ts b/tst/telemetry/TelemetryOptIn.test.ts new file mode 100644 index 000000000..e0c776ff9 --- /dev/null +++ b/tst/telemetry/TelemetryOptIn.test.ts @@ -0,0 +1,68 @@ +import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { window, workspace } from 'vscode'; +import { handleTelemetryOptIn } from '../../src/telemetry/TelemetryOptIn'; +import { LoggerFactory } from '../../src/utils/Logger'; + +vi.mock('vscode'); + +const settingKey = 'aws.iac.telemetry'; + +function createContext(state: Record) { + return { + globalState: { + get: (key: string) => state[key], + update: (key: string, value: unknown) => { + state[key] = value; + return Promise.resolve(); + }, + }, + } as any; +} + +describe('handleTelemetryOptIn', () => { + let settings: Record>; + + beforeEach(() => { + LoggerFactory.reset(); + LoggerFactory.initialize(window.createOutputChannel('test', { log: true })); + + settings = {}; + vi.mocked(workspace.getConfiguration).mockImplementation((section?: string) => { + const values = (settings[section ?? ''] ??= {}); + return { + get: vi.fn((key: string, defaultValue?: unknown) => values[key] ?? defaultValue), + update: vi.fn((key: string, value: unknown) => { + values[key] = value; + return Promise.resolve(); + }), + has: vi.fn(), + inspect: vi.fn(), + }; + }); + }); + + it('reads a previously recorded choice from aws.iac.telemetry.enabled', async () => { + settings[settingKey] = { enabled: true }; + const context = createContext({ 'aws.cloudformation.telemetry.hasResponded': true }); + + await expect(handleTelemetryOptIn(context)).resolves.toBe(true); + }); + + it('ignores aws.cloudformation.telemetry.enabled contributed by other extensions', async () => { + settings['aws.cloudformation.telemetry'] = { enabled: true }; + const context = createContext({ 'aws.cloudformation.telemetry.hasResponded': true }); + + await expect(handleTelemetryOptIn(context)).resolves.toBe(false); + }); + + it('persists the prompt answer under aws.iac.telemetry.enabled only', async () => { + vi.mocked(window.showInformationMessage).mockResolvedValue('Yes, Allow' as any); + const state: Record = {}; + + await expect(handleTelemetryOptIn(createContext(state))).resolves.toBe(true); + + expect(settings[settingKey]).toEqual({ enabled: true }); + expect(settings['aws.cloudformation.telemetry']?.enabled).toBeUndefined(); + expect(state['aws.cloudformation.telemetry.hasResponded']).toBe(true); + }); +}); diff --git a/tst/utils/Logger.test.ts b/tst/utils/Logger.test.ts new file mode 100644 index 000000000..1eb0f0fff --- /dev/null +++ b/tst/utils/Logger.test.ts @@ -0,0 +1,107 @@ +import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { workspace } from 'vscode'; +import { Logger, LoggerFactory } from '../../src/utils/Logger'; + +vi.mock('vscode'); + +function createChannel() { + return { + appendLine: vi.fn(), + trace: vi.fn(), + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + dispose: vi.fn(), + }; +} + +function configureLevel(level: string | undefined) { + vi.mocked(workspace.getConfiguration).mockReturnValue({ + get: vi.fn().mockImplementation((_key: string, defaultValue: unknown) => level ?? defaultValue), + update: vi.fn(), + has: vi.fn(), + inspect: vi.fn(), + }); +} + +describe('Logger', () => { + let channel: ReturnType; + + beforeEach(() => { + channel = createChannel(); + configureLevel(undefined); + }); + + it('writes through the channel method matching the level instead of appendLine', () => { + const log = new Logger('Extension', channel as any); + + log.info('Activating v1.0.0'); + log.warn('slow start'); + log.error('boom'); + + expect(channel.info).toHaveBeenCalledWith('[Extension] Activating v1.0.0'); + expect(channel.warn).toHaveBeenCalledWith('[Extension] slow start'); + expect(channel.error).toHaveBeenCalledWith('[Extension] boom'); + expect(channel.appendLine).not.toHaveBeenCalled(); + }); + + it('does not add its own timestamp or level prefix', () => { + const log = new Logger('Extension', channel as any); + + log.info('Activating v1.0.0'); + + const [line] = channel.info.mock.calls[0]; + expect(line).toBe('[Extension] Activating v1.0.0'); + expect(line).not.toMatch(/\d{2}:\d{2}:\d{2}/); + expect(line).not.toMatch(/Info:/); + }); + + it('emits the prefix once when both a message and data are given', () => { + const log = new Logger('BaseLspInstaller', channel as any); + const err = new Error('ENOENT'); + + log.error(err, 'Download failed'); + + const [line] = channel.error.mock.calls[0]; + expect(line.startsWith('[BaseLspInstaller] Download failed ')).toBe(true); + expect(line.match(/\[BaseLspInstaller\]/g)).toHaveLength(1); + expect(line).toContain('ENOENT'); + }); + + it('honors the configured log level', () => { + configureLevel('warn'); + const log = new Logger('Extension', channel as any); + + log.debug('d'); + log.info('i'); + log.warn('w'); + log.error('e'); + + expect(channel.debug).not.toHaveBeenCalled(); + expect(channel.info).not.toHaveBeenCalled(); + expect(channel.warn).toHaveBeenCalledWith('[Extension] w'); + expect(channel.error).toHaveBeenCalledWith('[Extension] e'); + }); + + it('emits debug through the channel debug method when configured', () => { + configureLevel('debug'); + const log = new Logger('Extension', channel as any); + + log.debug('details'); + + expect(channel.debug).toHaveBeenCalledWith('[Extension] details'); + }); + + it('LoggerFactory returns one logger per name bound to the initialized channel', () => { + LoggerFactory.reset(); + LoggerFactory.initialize(channel as any); + + const a = LoggerFactory.getLogger('A'); + const b = LoggerFactory.getLogger('A'); + a.info('hello'); + + expect(a).toBe(b); + expect(channel.info).toHaveBeenCalledWith('[A] hello'); + }); +}); From eda0e4d52c0d9ca422a67ffd1a564e491e0fcd29 Mon Sep 17 00:00:00 2001 From: Satyaki Ghosh Date: Fri, 2 Oct 2026 13:46:41 -0400 Subject: [PATCH 2/3] Update readme --- README.md | 1 - 1 file changed, 1 deletion(-) diff --git a/README.md b/README.md index a20c31be7..7d9eade5c 100644 --- a/README.md +++ b/README.md @@ -6,7 +6,6 @@ [![Node.js](https://img.shields.io/badge/dynamic/json?url=https%3A%2F%2Fraw.githubusercontent.com%2Faws-cloudformation%2Fcloudformation-vscode%2Frefs%2Fheads%2Fmain%2Fpackage.json&query=%24.engines.node&label=Node.js&color=339933&logo=node.js&logoColor=white)](https://github.com/aws-cloudformation/cloudformation-vscode/blob/main/package.json) [![Latest Release](https://img.shields.io/github/v/release/aws-cloudformation/cloudformation-vscode?include_prereleases&sort=semver)](https://github.com/aws-cloudformation/cloudformation-vscode/releases) -[![Downloads](https://img.shields.io/github/downloads/aws-cloudformation/cloudformation-vscode/total.svg)](https://github.com/aws-cloudformation/cloudformation-vscode/releases) ## Overview From ababb94dd8b8553bff93647738f2a3ae1f8230bb Mon Sep 17 00:00:00 2001 From: Satyaki Ghosh Date: Fri, 2 Oct 2026 13:47:58 -0400 Subject: [PATCH 3/3] Remove comments --- src/telemetry/TelemetryOptIn.ts | 3 --- 1 file changed, 3 deletions(-) diff --git a/src/telemetry/TelemetryOptIn.ts b/src/telemetry/TelemetryOptIn.ts index dad2ec8d4..249976200 100644 --- a/src/telemetry/TelemetryOptIn.ts +++ b/src/telemetry/TelemetryOptIn.ts @@ -15,9 +15,6 @@ const stateKeys = { unpersistedResponse: `${ExtensionConfigKey}.telemetry.unpersistedResponse`, } as const; -// Kept outside the `aws.cloudformation.*` namespace: other IDE clients of the language server -// contribute `aws.cloudformation.telemetry.enabled`, and consent given to one extension must not -// switch telemetry on or off for another. const telemetrySettingKey = 'aws.iac.telemetry'; const thirtyDaysMs = 30 * 24 * 60 * 60 * 1000; const promptTimeoutMs = 2500;