fix: support proxy correlation timeout notifications and additional proxy data

packages/proxy/lib/http/index.ts

@@ -427,5 +427,6 @@ export class Http {
 
   setProtocolManager (protocolManager: ProtocolManagerShape) {
     this.protocolManager = protocolManager
+    this.preRequests.setProtocolManager(protocolManager)
   }
 }

packages/proxy/lib/http/response-middleware.ts

@@ -691,6 +691,13 @@ const MaybeEndWithEmptyBody: ResponseMiddleware = function () {
       this.protocolManager.responseEndedWithEmptyBody({
         requestId,
         isCached: this.incomingRes.statusCode === 304,
+        timings: {
+          cdpRequestWillBeSentTimestamp: this.req.browserPreRequest.cdpRequestWillBeSentTimestamp,
+          cdpRequestWillBeSentReceivedTimestamp: this.req.browserPreRequest.cdpRequestWillBeSentReceivedTimestamp,
+          proxyRequestReceivedTimestamp: this.req.browserPreRequest.proxyRequestReceivedTimestamp,
+          cdpLagDuration: this.req.browserPreRequest.cdpLagDuration,
+          proxyRequestCorrelationDuration: this.req.browserPreRequest.proxyRequestCorrelationDuration,
+        },
       })
     }
 
@@ -797,15 +804,24 @@ const MaybeRemoveSecurity: ResponseMiddleware = function () {
 
 const GzipBody: ResponseMiddleware = async function () {
   if (this.protocolManager && this.req.browserPreRequest?.requestId) {
-    const requestId = getOriginalRequestId(this.req.browserPreRequest.requestId)
+    const preRequest = this.req.browserPreRequest
+    const requestId = getOriginalRequestId(preRequest.requestId)
 
     const span = telemetry.startSpan({ name: 'gzip:body:protocol-notification', parentSpan: this.resMiddlewareSpan, isVerbose })
+
     const resultingStream = this.protocolManager.responseStreamReceived({
       requestId,
       responseHeaders: this.incomingRes.headers,
       isAlreadyGunzipped: this.isGunzipped,
       responseStream: this.incomingResStream,
       res: this.res,
+      timings: {
+        cdpRequestWillBeSentTimestamp: preRequest.cdpRequestWillBeSentTimestamp,
+        cdpRequestWillBeSentReceivedTimestamp: preRequest.cdpRequestWillBeSentReceivedTimestamp,
+        proxyRequestReceivedTimestamp: preRequest.proxyRequestReceivedTimestamp,
+        cdpLagDuration: preRequest.cdpLagDuration,
+        proxyRequestCorrelationDuration: preRequest.proxyRequestCorrelationDuration,
+      },
     })
 
     if (resultingStream) {

packages/proxy/lib/http/util/prerequests.ts

@@ -1,7 +1,9 @@
 import type {
   CypressIncomingRequest,
   BrowserPreRequest,
+  BrowserPreRequestWithTimings,
 } from '@packages/proxy'
+import type { ProtocolManagerShape } from '@packages/types'
 import Debug from 'debug'
 
 const debug = Debug('cypress:proxy:http:util:prerequests')
@@ -19,17 +21,20 @@ process.once('exit', () => {
   debug('metrics: %o', metrics)
 })
 
-export type GetPreRequestCb = (browserPreRequest?: BrowserPreRequest) => void
+export type GetPreRequestCb = (browserPreRequest?: BrowserPreRequestWithTimings) => void
 
 type PendingRequest = {
   ctxDebug
   callback: GetPreRequestCb
   timeout: NodeJS.Timeout
+  timedOut?: boolean
+  proxyRequestReceivedTimestamp: number
 }
 
 type PendingPreRequest = {
   browserPreRequest: BrowserPreRequest
-  timestamp: number
+  cdpRequestWillBeSentTimestamp: number
+  cdpRequestWillBeSentReceivedTimestamp: number
 }
 
 /**
@@ -82,11 +87,12 @@ export class PreRequests {
   pendingPreRequests = new QueueMap<PendingPreRequest>()
   pendingRequests = new QueueMap<PendingRequest>()
   sweepIntervalTimer: NodeJS.Timeout
+  protocolManager?: ProtocolManagerShape
 
   constructor (
-    requestTimeout = 500,
+    requestTimeout = 2000,
     // 10 seconds
-    sweepInterval = 1000 * 10,
+    sweepInterval = 10000,
   ) {
     // If a request comes in and we don't have a matching pre-request after this timeout,
     // we invoke the request callback to tell the server to proceed (we don't want to block
@@ -103,8 +109,8 @@ export class PreRequests {
     this.sweepIntervalTimer = setInterval(() => {
       const now = Date.now()
 
-      this.pendingPreRequests.removeMatching(({ timestamp, browserPreRequest }) => {
-        if (timestamp + this.sweepInterval < now) {
+      this.pendingPreRequests.removeMatching(({ cdpRequestWillBeSentReceivedTimestamp, browserPreRequest }) => {
+        if (cdpRequestWillBeSentReceivedTimestamp + this.sweepInterval < now) {
           debugVerbose('timed out unmatched pre-request: %o', browserPreRequest)
           metrics.unmatchedPreRequests++
 
@@ -123,16 +129,39 @@ export class PreRequests {
 
     if (pendingRequest) {
       debugVerbose('Incoming pre-request %s matches pending request. %o', key, browserPreRequest)
-      clearTimeout(pendingRequest.timeout)
-      pendingRequest.callback(browserPreRequest)
+      if (!pendingRequest.timedOut) {
+        clearTimeout(pendingRequest.timeout)
+        pendingRequest.callback({
+          ...browserPreRequest,
+          cdpRequestWillBeSentTimestamp: browserPreRequest.cdpRequestWillBeSentTimestamp,
+          cdpRequestWillBeSentReceivedTimestamp: browserPreRequest.cdpRequestWillBeSentReceivedTimestamp,
+          proxyRequestReceivedTimestamp: pendingRequest.proxyRequestReceivedTimestamp,
+          cdpLagDuration: browserPreRequest.cdpRequestWillBeSentReceivedTimestamp - browserPreRequest.cdpRequestWillBeSentTimestamp,
+          proxyRequestCorrelationDuration: Math.max(browserPreRequest.cdpRequestWillBeSentReceivedTimestamp - pendingRequest.proxyRequestReceivedTimestamp, 0),
+        })
+
+        return
+      }
+
+      this.protocolManager?.responseStreamTimedOut({
+        requestId: browserPreRequest.requestId,
+        timings: {
+          cdpRequestWillBeSentTimestamp: browserPreRequest.cdpRequestWillBeSentTimestamp,
+          cdpRequestWillBeSentReceivedTimestamp: browserPreRequest.cdpRequestWillBeSentReceivedTimestamp,
+          proxyRequestReceivedTimestamp: pendingRequest.proxyRequestReceivedTimestamp,
+          cdpLagDuration: browserPreRequest.cdpRequestWillBeSentReceivedTimestamp - browserPreRequest.cdpRequestWillBeSentTimestamp,
+          proxyRequestCorrelationDuration: Math.max(browserPreRequest.cdpRequestWillBeSentReceivedTimestamp - pendingRequest.proxyRequestReceivedTimestamp, 0),
+        },
+      })
 
       return
     }
 
     debugVerbose('Caching pre-request %s to be matched later. %o', key, browserPreRequest)
     this.pendingPreRequests.push(key, {
       browserPreRequest,
-      timestamp: Date.now(),
+      cdpRequestWillBeSentTimestamp: browserPreRequest.cdpRequestWillBeSentTimestamp,
+      cdpRequestWillBeSentReceivedTimestamp: browserPreRequest.cdpRequestWillBeSentReceivedTimestamp,
     })
   }
 
@@ -143,29 +172,43 @@ export class PreRequests {
   }
 
   get (req: CypressIncomingRequest, ctxDebug, callback: GetPreRequestCb) {
+    const proxyRequestReceivedTimestamp = performance.now() + performance.timeOrigin
+
     metrics.proxyRequestsReceived++
     const key = `${req.method}-${req.proxiedUrl}`
     const pendingPreRequest = this.pendingPreRequests.shift(key)
 
     if (pendingPreRequest) {
       metrics.immediatelyMatchedRequests++
       ctxDebug('Incoming request %s matches known pre-request: %o', key, pendingPreRequest)
-      callback(pendingPreRequest.browserPreRequest)
+      callback({
+        ...pendingPreRequest.browserPreRequest,
+        cdpRequestWillBeSentTimestamp: pendingPreRequest.cdpRequestWillBeSentTimestamp,
+        cdpRequestWillBeSentReceivedTimestamp: pendingPreRequest.cdpRequestWillBeSentReceivedTimestamp,
+        proxyRequestReceivedTimestamp,
+        cdpLagDuration: pendingPreRequest.cdpRequestWillBeSentReceivedTimestamp - pendingPreRequest.cdpRequestWillBeSentTimestamp,
+        proxyRequestCorrelationDuration: Math.max(pendingPreRequest.cdpRequestWillBeSentReceivedTimestamp - proxyRequestReceivedTimestamp, 0),
+      })
 
       return
     }
 
     const pendingRequest: PendingRequest = {
       ctxDebug,
       callback,
+      proxyRequestReceivedTimestamp: performance.now() + performance.timeOrigin,
       timeout: setTimeout(() => {
         ctxDebug('Never received pre-request for request %s after waiting %sms. Continuing without one.', key, this.requestTimeout)
         metrics.unmatchedRequests++
-        this.pendingRequests.removeExact(key, pendingRequest)
+        pendingRequest.timedOut = true
         callback()
       }, this.requestTimeout),
     }
 
     this.pendingRequests.push(key, pendingRequest)
   }
+
+  setProtocolManager (protocolManager: ProtocolManagerShape) {
+    this.protocolManager = protocolManager
+  }
 }

packages/proxy/lib/types.ts

@@ -1,5 +1,6 @@
 import type { Readable } from 'stream'
 import type { Request, Response } from 'express'
+import type { ProxyTimings } from '@packages/types'
 import type { ResourceType } from '@packages/net-stubbing'
 import type { BackendRoute } from '@packages/net-stubbing/lib/server/types'
 
@@ -10,7 +11,7 @@ export type CypressIncomingRequest = Request & {
   proxiedUrl: string
   abort: () => void
   requestId: string
-  browserPreRequest?: BrowserPreRequest
+  browserPreRequest?: BrowserPreRequestWithTimings
   body?: string
   responseTimeout?: number
   followRedirect?: boolean
@@ -60,8 +61,12 @@ export type BrowserPreRequest = {
   resourceType: ResourceType
   originalResourceType: string | undefined
   errorHandled?: boolean
+  cdpRequestWillBeSentTimestamp: number
+  cdpRequestWillBeSentReceivedTimestamp: number
 }
 
+export type BrowserPreRequestWithTimings = BrowserPreRequest & ProxyTimings
+
 /**
  * Notification that the browser has received a response for a request for which a pre-request may have been emitted.
  */

packages/proxy/test/unit/http/response-middleware.spec.ts

@@ -1827,6 +1827,11 @@ describe('http/response-middleware', function () {
         req: {
           browserPreRequest: {
             requestId: '123',
+            cdpRequestWillBeSentTimestamp: 1,
+            cdpRequestWillBeSentReceivedTimestamp: 2,
+            proxyRequestReceivedTimestamp: 3,
+            cdpLagDuration: 4,
+            proxyRequestCorrelationDuration: 5,
           },
         },
         incomingRes: {
@@ -1840,6 +1845,11 @@ describe('http/response-middleware', function () {
           sinon.match(function (actual) {
             expect(actual.requestId).to.equal('123')
             expect(actual.isCached).to.equal(true)
+            expect(actual.timings.cdpRequestWillBeSentTimestamp).to.equal(1)
+            expect(actual.timings.cdpRequestWillBeSentReceivedTimestamp).to.equal(2)
+            expect(actual.timings.proxyRequestReceivedTimestamp).to.equal(3)
+            expect(actual.timings.cdpLagDuration).to.equal(4)
+            expect(actual.timings.proxyRequestCorrelationDuration).to.equal(5)
 
             return true
           }),
@@ -2259,6 +2269,11 @@ describe('http/response-middleware', function () {
         req: {
           browserPreRequest: {
             requestId: '123',
+            cdpRequestWillBeSentTimestamp: 1,
+            cdpRequestWillBeSentReceivedTimestamp: 2,
+            proxyRequestReceivedTimestamp: 3,
+            cdpLagDuration: 4,
+            proxyRequestCorrelationDuration: 5,
           },
         },
         res,
@@ -2278,6 +2293,11 @@ describe('http/response-middleware', function () {
             expect(actual.isAlreadyGunzipped).to.equal(true)
             expect(actual.responseStream).to.equal(stream)
             expect(actual.res).to.equal(res)
+            expect(actual.timings.cdpRequestWillBeSentTimestamp).to.equal(1)
+            expect(actual.timings.cdpRequestWillBeSentReceivedTimestamp).to.equal(2)
+            expect(actual.timings.proxyRequestReceivedTimestamp).to.equal(3)
+            expect(actual.timings.cdpLagDuration).to.equal(4)
+            expect(actual.timings.proxyRequestCorrelationDuration).to.equal(5)
 
             return true
           }),