From 39cee4188cf13808951584624758b457c45a6809 Mon Sep 17 00:00:00 2001 From: Alfonso Noriega Date: Fri, 29 May 2026 16:31:07 +0200 Subject: [PATCH] Fix auto-upgrade telemetry reporting order --- .../cli-kit/src/public/node/analytics.test.ts | 36 ++++++++++++++++++- packages/cli-kit/src/public/node/analytics.ts | 4 +-- .../src/public/node/hooks/postrun.test.ts | 32 ++++++++++++++++- .../cli-kit/src/public/node/hooks/postrun.ts | 16 +++++++-- packages/cli-kit/src/public/node/metadata.ts | 1 + 5 files changed, 83 insertions(+), 6 deletions(-) diff --git a/packages/cli-kit/src/public/node/analytics.test.ts b/packages/cli-kit/src/public/node/analytics.test.ts index 8d1a68fe80c..975de8b6e77 100644 --- a/packages/cli-kit/src/public/node/analytics.test.ts +++ b/packages/cli-kit/src/public/node/analytics.test.ts @@ -13,7 +13,7 @@ import {inTemporaryDirectory, touchFile, mkdir} from './fs.js' import {joinPath, dirname} from './path.js' import {publishMonorailEvent} from './monorail.js' import {mockAndCaptureOutput} from './testing/output.js' -import {addPublicMetadata} from './metadata.js' +import {addPublicMetadata, addSensitiveMetadata} from './metadata.js' import {sendErrorToBugsnag} from './error-handler.js' import {hashString} from './crypto.js' import * as store from '../../private/node/analytics/storage.js' @@ -124,6 +124,40 @@ describe('event tracking', () => { }) }) + test('uses a recorded command end time when reporting after postrun work', async () => { + await inProjectWithFile('package.json', async (args) => { + // Given + const commandContent = {command: 'dev', topic: 'app'} + const startTime = currentDate.getTime() - 100 + const commandEndTime = currentDate.getTime() + await startAnalytics({commandContent, args, currentTime: startTime}) + await addSensitiveMetadata(() => ({ + commandStartOptions: { + startTime, + endTime: commandEndTime, + startCommand: commandContent.command, + startArgs: args, + }, + })) + vi.setSystemTime(new Date(commandEndTime + 60000)) + + // When + const config = { + runHook: vi.fn().mockResolvedValue({successes: [], failures: []}), + plugins: [], + } as any + await reportAnalyticsEvent({config, exitMode: 'ok'}) + + // Then + expect(publishEventMock).toHaveBeenCalledOnce() + expect(publishEventMock.mock.calls[0]![1]).toMatchObject({ + time_start: startTime, + time_end: commandEndTime, + total_time: 100, + }) + }) + }) + test('sends the expected data to Monorail when there is an error message', async () => { await inProjectWithFile('package.json', async (args) => { // Given diff --git a/packages/cli-kit/src/public/node/analytics.ts b/packages/cli-kit/src/public/node/analytics.ts index 5578e3af328..f8269159b52 100644 --- a/packages/cli-kit/src/public/node/analytics.ts +++ b/packages/cli-kit/src/public/node/analytics.ts @@ -117,8 +117,8 @@ async function buildPayload({config, errorMessage, exitMode}: ReportAnalyticsEve outputDebug('Unable to log analytics event - no information on executed command') return } - const {startCommand, startArgs, startTime} = commandStartOptions - const currentTime = new Date().getTime() + const {startCommand, startArgs, startTime, endTime} = commandStartOptions + const currentTime = endTime ?? new Date().getTime() // All bundled plugins appear as `@shopify/cli` in the payload const {'@shopify/cli': internalPluginsPublic, ...externalPluginsPublic} = await fanoutHooks( diff --git a/packages/cli-kit/src/public/node/hooks/postrun.test.ts b/packages/cli-kit/src/public/node/hooks/postrun.test.ts index e3ccd84585c..fdcd2613109 100644 --- a/packages/cli-kit/src/public/node/hooks/postrun.test.ts +++ b/packages/cli-kit/src/public/node/hooks/postrun.test.ts @@ -1,4 +1,4 @@ -import {autoUpgradeIfNeeded} from './postrun.js' +import {autoUpgradeIfNeeded, hook} from './postrun.js' import {mockAndCaptureOutput} from '../testing/output.js' import { getOutputUpdateCLIReminder, @@ -9,6 +9,7 @@ import { import {isMajorVersionChange} from '../version.js' import {inferPackageManagerForGlobalCLI} from '../is-global.js' import {addPublicMetadata} from '../metadata.js' +import {reportAnalyticsEvent} from '../analytics.js' import {describe, expect, test, vi, afterEach} from 'vitest' vi.mock('../upgrade.js', async (importOriginal) => { @@ -38,6 +39,14 @@ vi.mock('../is-global.js', async (importOriginal) => { } }) +vi.mock('../analytics.js', () => ({ + reportAnalyticsEvent: vi.fn().mockResolvedValue(undefined), +})) + +vi.mock('./deprecations.js', () => ({ + postrun: vi.fn(), +})) + vi.mock('../metadata.js', async (importOriginal) => { const actual: any = await importOriginal() return { @@ -61,9 +70,30 @@ vi.mock('../../../private/node/conf-store.js', async (importOriginal) => { afterEach(() => { mockAndCaptureOutput().clear() vi.mocked(addPublicMetadata).mockClear() + vi.mocked(reportAnalyticsEvent).mockClear() vi.mocked(hasBlockingAutoUpgradeNotification).mockResolvedValue(false) }) +describe('postrun hook', () => { + test('reports analytics after auto-upgrade so auto-upgrade metadata is available', async () => { + const config = {plugins: new Map(), runHook: vi.fn()} as any + const Command = {id: 'app dev'} as any + vi.mocked(versionToAutoUpgrade).mockReturnValue('3.100.0') + vi.mocked(isMajorVersionChange).mockReturnValue(false) + vi.mocked(runCLIUpgrade).mockResolvedValue(undefined) + + await hook.call({} as any, {config, Command} as any) + + expect(runCLIUpgrade).toHaveBeenCalled() + expect(reportAnalyticsEvent).toHaveBeenCalledWith({config, exitMode: 'ok'}) + expect(vi.mocked(runCLIUpgrade).mock.invocationCallOrder[0]!).toBeLessThan( + vi.mocked(reportAnalyticsEvent).mock.invocationCallOrder[0]!, + ) + const calls = vi.mocked(addPublicMetadata).mock.calls.map((call) => call[0]()) + expect(calls).toContainEqual(expect.objectContaining({env_auto_upgrade_success: true})) + }) +}) + describe('autoUpgradeIfNeeded', () => { test('runs the upgrade when versionToAutoUpgrade returns a version', async () => { // Given diff --git a/packages/cli-kit/src/public/node/hooks/postrun.ts b/packages/cli-kit/src/public/node/hooks/postrun.ts index 09146d0cd8c..8718e50218e 100644 --- a/packages/cli-kit/src/public/node/hooks/postrun.ts +++ b/packages/cli-kit/src/public/node/hooks/postrun.ts @@ -56,8 +56,16 @@ export function waitForPostRunHookAndExit(): void { export const hook: Hook.Postrun = async ({config, Command}) => { await detectStopCommand(Command as unknown as typeof Command) - const {reportAnalyticsEvent} = await import('../analytics.js') - await reportAnalyticsEvent({config, exitMode: 'ok'}) + const metadata = await import('../metadata.js') + const {commandStartOptions} = metadata.getAllSensitiveMetadata() + if (commandStartOptions) { + await metadata.addSensitiveMetadata(() => ({ + commandStartOptions: { + ...commandStartOptions, + endTime: new Date().getTime(), + }, + })) + } const {postrun: deprecationsHook} = await import('./deprecations.js') deprecationsHook(Command) @@ -67,6 +75,10 @@ export const hook: Hook.Postrun = async ({config, Command}) => { outputDebug(`Completed command ${command}`) if (!command.includes('notifications') && !command.includes('upgrade')) await autoUpgradeIfNeeded() + + const {reportAnalyticsEvent} = await import('../analytics.js') + await reportAnalyticsEvent({config, exitMode: 'ok'}) + postRunHookCompleted = true } diff --git a/packages/cli-kit/src/public/node/metadata.ts b/packages/cli-kit/src/public/node/metadata.ts index 1b6223f7b4b..30e05719e55 100644 --- a/packages/cli-kit/src/public/node/metadata.ts +++ b/packages/cli-kit/src/public/node/metadata.ts @@ -189,6 +189,7 @@ const coreData = createRuntimeMetadataContainer< { commandStartOptions: { startTime: number + endTime?: number startCommand: string startTopic?: string startArgs: string[]