misc: receive afterSpec durations from app capture code, and report them to the Cloud API

cli/CHANGELOG.md

@@ -7,6 +7,10 @@ _Released 5/28/2024 (PENDING)_
 
 - Pre-emptively fix behavior with Chrome for when `unload` events are forcefully deprecated by using `pagehide` as a proxy. Fixes [#29241](https://github.com/cypress-io/cypress/issues/29241).
 
+**Misc:**
+
+- Report afterSpec durations to Cloud API when running in record mode with Test Replay enabled. Addressed in [#29500](https://github.com/cypress-io/cypress/pull/29500).
+
 ## 13.10.0
 
 _Released 5/21/2024_

packages/server/lib/cloud/api/index.ts

@@ -22,6 +22,7 @@ import type { OptionsWithUrl } from 'request-promise'
 import { fs } from '../../util/fs'
 import ProtocolManager from '../protocol'
 import type { ProjectBase } from '../../project-base'
+import type { AfterSpecDurations } from '@packages/types'
 
 const THIRTY_SECONDS = humanInterval('30 seconds')
 const SIXTY_SECONDS = humanInterval('60 seconds')
@@ -289,6 +290,9 @@ export type ProtocolMetadata = ArtifactMetadata & {
     size: number
     offset: number
   }
+  afterSpecDurations?: AfterSpecDurations & {
+    afterSpecTotal: number
+  }
 }
 
 export type UpdateInstanceArtifactsPayload = {
@@ -508,6 +512,8 @@ export default {
   },
 
   updateInstanceArtifacts (options: UpdateInstanceArtifactsOptions, body: UpdateInstanceArtifactsPayload) {
+    debug('PUT %s %o', recordRoutes.instanceArtifacts(options.instanceId), body)
+
     return retryWithBackoff((attemptIndex) => {
       return rp.put({
         url: recordRoutes.instanceArtifacts(options.instanceId),

packages/server/lib/cloud/artifacts/artifact.ts

@@ -1,6 +1,6 @@
 import Debug from 'debug'
 import { performance } from 'perf_hooks'
-
+import type { AfterSpecDurations } from '@packages/types'
 const debug = Debug('cypress:server:cloud:artifact')
 
 const isAggregateError = (err: any): err is AggregateError => {
@@ -32,12 +32,15 @@ export interface ArtifactUploadResult {
   key: ArtifactKind
   errorStack?: string
   allErrors?: Error[]
+  uploadDuration?: number
+  originalError?: Error
+  afterSpecDurations?: AfterSpecDurations & {
+    afterSpecTotal: number
+  }
   specAccess?: {
     offset: number
     size: number
   }
-  uploadDuration?: number
-  originalError?: Error
 }
 
 export type ArtifactUploadStrategy<T> = (filePath: string, uploadUrl: string, fileSize: number | bigint) => T

packages/server/lib/cloud/protocol.ts

@@ -7,15 +7,14 @@ import fs from 'fs-extra'
 import Module from 'module'
 import os from 'os'
 import path from 'path'
-
 import { agent } from '@packages/network'
 import pkg from '@packages/root'
-
+import { performance } from 'perf_hooks'
 import env from '../util/env'
 import { putProtocolArtifact } from './api/put_protocol_artifact'
 
 import type { Readable } from 'stream'
-import type { ProtocolManagerShape, AppCaptureProtocolInterface, CDPClient, ProtocolError, CaptureArtifact, ProtocolErrorReport, ProtocolCaptureMethod, ProtocolManagerOptions, ResponseStreamOptions, ResponseEndedWithEmptyBodyOptions, ResponseStreamTimedOutOptions } from '@packages/types'
+import type { ProtocolManagerShape, AppCaptureProtocolInterface, CDPClient, ProtocolError, CaptureArtifact, ProtocolErrorReport, ProtocolCaptureMethod, ProtocolManagerOptions, ResponseStreamOptions, ResponseEndedWithEmptyBodyOptions, ResponseStreamTimedOutOptions, AfterSpecDurations } from '@packages/types'
 
 const routes = require('./routes')
 
@@ -25,7 +24,7 @@ const debugVerbose = Debug('cypress-verbose:server:protocol')
 const CAPTURE_ERRORS = !process.env.CYPRESS_LOCAL_PROTOCOL_PATH
 const DELETE_DB = !process.env.CYPRESS_LOCAL_PROTOCOL_PATH
 
-const DB_SIZE_LIMIT = 5000000000
+export const DB_SIZE_LIMIT = 5000000000
 
 const dbSizeLimit = () => {
   return env.get('CYPRESS_INTERNAL_SYSTEM_TESTS') === '1' ?
@@ -59,6 +58,9 @@ export class ProtocolManager implements ProtocolManagerShape {
   private _protocol: AppCaptureProtocolInterface | undefined
   private _runnableId: string | undefined
   private _captureHash: string | undefined
+  private _afterSpecDurations: AfterSpecDurations & {
+    afterSpecTotal: number
+  } | undefined
 
   get protocolEnabled (): boolean {
     return !!this._protocol
@@ -130,6 +132,8 @@ export class ProtocolManager implements ProtocolManagerShape {
   }
 
   beforeSpec (spec: { instanceId: string }) {
+    this._afterSpecDurations = undefined
+
     if (!this._protocol) {
       return
     }
@@ -170,7 +174,30 @@ export class ProtocolManager implements ProtocolManagerShape {
   }
 
   async afterSpec () {
-    await this.invokeAsync('afterSpec', { isEssential: true })
+    const startTime = performance.now() + performance.timeOrigin
+
+    try {
+      const ret = await this.invokeAsync('afterSpec', { isEssential: true })
+      const durations = ret?.durations
+
+      const afterSpecTotal = (performance.now() + performance.timeOrigin) - startTime
+
+      this._afterSpecDurations = {
+        afterSpecTotal,
+        ...(durations ? durations : {}),
+      }
+
+      debug('Persisting after spec durations in state: %O', this._afterSpecDurations)
+
+      return undefined
+    } catch (e) {
+      // rethrow; this is try/catch so we can 'finally' ascertain duration
+      this._afterSpecDurations = {
+        afterSpecTotal: (performance.now() + performance.timeOrigin - startTime),
+      }
+
+      throw e
+    }
   }
 
   async beforeTest (test: { id: string } & Record<string, any>) {
@@ -277,11 +304,7 @@ export class ProtocolManager implements ProtocolManagerShape {
     }
   }
 
-  async uploadCaptureArtifact ({ uploadUrl, fileSize, filePath }: CaptureArtifact): Promise<{
-    success: boolean
-    fileSize: number | bigint
-    specAccess: ReturnType<AppCaptureProtocolInterface['getDbMetadata']>
-  } | undefined> {
+  async uploadCaptureArtifact ({ uploadUrl, fileSize, filePath }: CaptureArtifact, captureErrorsOverride?: boolean) {
     if (!this._protocol || !filePath || !this._db) {
       debug('not uploading due to one of the following being falsy: %O', {
         _protocol: !!this._protocol,
@@ -292,6 +315,8 @@ export class ProtocolManager implements ProtocolManagerShape {
       return
     }
 
+    const captureErrors = captureErrorsOverride ?? CAPTURE_ERRORS
+
     debug(`uploading %s to %s with a file size of %s`, filePath, uploadUrl, fileSize)
 
     try {
@@ -301,9 +326,12 @@ export class ProtocolManager implements ProtocolManagerShape {
         fileSize,
         success: true,
         specAccess: this._protocol.getDbMetadata(),
+        ...(this._afterSpecDurations ? {
+          afterSpecDurations: this._afterSpecDurations,
+        } : {}),
       }
     } catch (e) {
-      if (CAPTURE_ERRORS) {
+      if (captureErrors) {
         this._errors.push({
           error: e,
           captureMethod: 'uploadCaptureArtifact',
@@ -403,9 +431,9 @@ export class ProtocolManager implements ProtocolManagerShape {
    * Abstracts invoking a synchronous method on the AppCaptureProtocol instance, so we can handle
    * errors in a uniform way
    */
-  private async invokeAsync <K extends ProtocolAsyncMethods> (method: K, { isEssential }: { isEssential: boolean }, ...args: Parameters<AppCaptureProtocolInterface[K]>) {
+  private async invokeAsync <K extends ProtocolAsyncMethods> (method: K, { isEssential }: { isEssential: boolean }, ...args: Parameters<AppCaptureProtocolInterface[K]>): Promise<ReturnType<AppCaptureProtocolInterface[K]> | undefined> {
     if (!this._protocol) {
-      return
+      return undefined
     }
 
     try {
@@ -417,6 +445,8 @@ export class ProtocolManager implements ProtocolManagerShape {
       } else {
         throw error
       }
+
+      return undefined
     }
   }
 

packages/server/test/unit/cloud/protocol_spec.ts

@@ -1,20 +1,24 @@
-import { proxyquire } from '../../spec_helper'
+import { proxyquire, sinon } from '../../spec_helper'
 import path from 'path'
 import os from 'os'
 import type { AppCaptureProtocolInterface, ProtocolManagerShape } from '@packages/types'
 import { expect } from 'chai'
 import { EventEmitter } from 'stream'
 import esbuild from 'esbuild'
+import fs from 'fs-extra'
+import type { SinonStub } from 'sinon'
 
 class TestClient extends EventEmitter {
   send: sinon.SinonStub = sinon.stub()
 }
 
 const mockDb = sinon.stub()
 const mockDatabase = sinon.stub().returns(mockDb)
+const mockPutProtocolArtifact = sinon.stub()
 
-const { ProtocolManager } = proxyquire('../lib/cloud/protocol', {
+const { ProtocolManager, DB_SIZE_LIMIT } = proxyquire('../lib/cloud/protocol', {
   'better-sqlite3': mockDatabase,
+  './api/put_protocol_artifact': { putProtocolArtifact: mockPutProtocolArtifact },
 }) as typeof import('@packages/server/lib/cloud/protocol')
 
 const { outputFiles: [{ contents: stubProtocolRaw }] } = esbuild.buildSync({
@@ -119,12 +123,14 @@ describe('lib/cloud/protocol', () => {
     })
   })
 
-  it('should be able to clean up after a spec', async () => {
-    sinon.stub(protocol, 'afterSpec')
+  describe('.afterSpec', () => {
+    it('invokes the protocol manager afterSpec fn', async () => {
+      sinon.stub(protocol, 'afterSpec')
 
-    await protocolManager.afterSpec()
+      await protocolManager.afterSpec()
 
-    expect(protocol.afterSpec).to.be.called
+      expect(protocol.afterSpec).to.be.called
+    })
   })
 
   it('should be able to handle pre-after test', async () => {
@@ -289,4 +295,124 @@ describe('lib/cloud/protocol', () => {
 
     expect(protocol.resetTest).to.be.calledWith(testId)
   })
+
+  describe('.uploadCaptureArtifact()', () => {
+    let filePath: string
+    let fileSize: number
+    let uploadUrl: string
+    let expectedAfterSpecTotal: number
+    let offset: number
+    let size: number
+    let instanceId: string
+    let clock
+
+    describe('when protocol is initialized, and spec has finished', () => {
+      const expectedAfterSpecDurations = {
+        durations: {
+          drainCDPEvents: 1,
+          finalizePendingRunnables: 3,
+          drainAUTEvents: 5,
+          resolveBodyPromises: 7,
+          closeDb: 11,
+          teardownBindings: 13,
+        },
+      }
+
+      beforeEach(async () => {
+        filePath = '/foo/bar'
+        fileSize = 1000
+        uploadUrl = 'http://fake.test/upload_url'
+        offset = 10
+        size = 100
+        instanceId = 'abc123'
+
+        sinon.stub(protocol, 'getDbMetadata').returns({ offset, size })
+        sinon.stub(fs, 'unlink').withArgs(filePath).resolves()
+        protocolManager.beforeSpec({ instanceId })
+
+        expectedAfterSpecTotal = 225
+
+        clock = sinon.useFakeTimers()
+        sinon.stub(performance, 'timeOrigin').value(0)
+        sinon.stub(protocol, 'afterSpec').callsFake(async () => {
+          await clock.tickAsync(expectedAfterSpecTotal)
+
+          return expectedAfterSpecDurations
+        })
+
+        await protocolManager.afterSpec()
+      })
+
+      afterEach(() => {
+        clock.restore()
+      })
+
+      describe('when upload succeeds', () => {
+        beforeEach(() => {
+          mockPutProtocolArtifact.withArgs(filePath, DB_SIZE_LIMIT, uploadUrl).resolves()
+        })
+
+        it('unlinks the db & returns fileSize, afterSpecDuration, success=true, and the db metadata', async () => {
+          const res = await protocolManager.uploadCaptureArtifact({ uploadUrl, filePath, fileSize })
+
+          expect(res).not.to.be.undefined
+          expect(res).to.include({
+            fileSize,
+            success: true,
+          })
+
+          expect(res?.afterSpecDurations).to.include({
+            afterSpecTotal: expectedAfterSpecTotal,
+            ...expectedAfterSpecDurations.durations,
+          })
+
+          // @ts-ignore
+          expect(res?.specAccess.offset).to.eq(offset)
+          // @ts-ignore
+          expect(res?.specAccess.size).to.eq(size)
+
+          expect(fs.unlink).to.have.been.called
+        })
+      })
+
+      describe('when upload fails', () => {
+        let err
+
+        beforeEach(() => {
+          err = new Error()
+
+          ;(mockPutProtocolArtifact as SinonStub).withArgs(filePath, DB_SIZE_LIMIT, uploadUrl).rejects(err)
+        })
+
+        describe('and CAPTURE_ERRORs is enabled', () => {
+          it('unlinks the db & rethrows the error', async () => {
+            let threw = false
+
+            try {
+              await protocolManager.uploadCaptureArtifact({ uploadUrl, filePath, fileSize }, true)
+            } catch (e) {
+              threw = true
+              expect(e).to.eq(err)
+            }
+            expect(threw).to.be.true
+            expect(fs.unlink).to.be.called
+          })
+        })
+
+        describe('and CAPTURE_ERRORS is not enabled', () => {
+          it('unlinks the db and does not rethrow', async () => {
+            let threw = false
+
+            try {
+              await protocolManager.uploadCaptureArtifact({ uploadUrl, filePath, fileSize }, false)
+            } catch (e) {
+              threw = true
+            }
+            expect(threw).to.be.false
+            expect(fs.unlink).to.be.called
+          })
+        })
+      })
+    })
+  })
 })