Merge pull request #7670 from Shopify/fix-auto-upgrade-telemetry-order

Fix auto-upgrade telemetry reporting order

Author: alfonso-noriega

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

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(

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

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
 }
 

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[]