fix: support proxy correlation timeout notifications and additional p…

…roxy data (#27976)

cli/CHANGELOG.md

@@ -8,6 +8,7 @@ _Released 10/03/2023 (PENDING)_
 - Fixed an issue where requests were correlated in the wrong order in the proxy. This could cause an issue where the wrong request is used for `cy.intercept` or assets (e.g. stylesheets or images) may not properly be available in Test Replay. Addressed in [#27892](https://github.com/cypress-io/cypress/pull/27892).
 - Fixed an issue where a crashed Chrome renderer can cause the Test Replay recorder to hang. Addressed in [#27909](https://github.com/cypress-io/cypress/pull/27909).
 - Fixed an issue where multiple responses yielded from calls to `cy.wait()` would sometimes be out of order. Fixes [#27337](https://github.com/cypress-io/cypress/issues/27337).
+- Fixed an issue where requests were timing out in the proxy. This could cause an issue where the wrong request is used for `cy.intercept` or assets (e.g. stylesheets or images) may not properly be available in Test Replay. Addressed in [#27976](https://github.com/cypress-io/cypress/pull/27976)
 - Fixed an issue where Test Replay couldn't record tests due to issues involving `GLIBC`. Fixed deprecation warnings during the rebuild of better-sqlite3. Fixes [#27891](https://github.com/cypress-io/cypress/issues/27891) and [#27902](https://github.com/cypress-io/cypress/issues/27902).
 - Enables test replay for executed specs in runs that have a spec that causes a browser crash. Addressed in [#27786](https://github.com/cypress-io/cypress/pull/27786)
 

packages/proxy/lib/http/index.ts

@@ -425,7 +425,12 @@ export class Http {
     this.preRequests.removePending(requestId)
   }
 
+  addPendingUrlWithoutPreRequest (url: string) {
+    this.preRequests.addPendingUrlWithoutPreRequest(url)
+  }
+
   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,16 +21,23 @@ 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
+  cdpRequestWillBeSentTimestamp: number
+  cdpRequestWillBeSentReceivedTimestamp: number
+}
+
+type PendingUrlWithoutPreRequest = {
   timestamp: number
 }
 
@@ -81,12 +90,14 @@ export class PreRequests {
   sweepInterval: number
   pendingPreRequests = new QueueMap<PendingPreRequest>()
   pendingRequests = new QueueMap<PendingRequest>()
+  pendingUrlsWithoutPreRequests = new QueueMap<PendingUrlWithoutPreRequest>()
   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 +114,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++
 
@@ -113,6 +124,10 @@ export class PreRequests {
 
         return true
       })
+
+      this.pendingUrlsWithoutPreRequests.removeMatching(({ timestamp }) => {
+        return timestamp + this.sweepInterval >= now
+      })
     }, this.sweepInterval)
   }
 
@@ -122,16 +137,54 @@ export class PreRequests {
     const pendingRequest = this.pendingRequests.shift(key)
 
     if (pendingRequest) {
+      const timings = {
+        cdpRequestWillBeSentTimestamp: browserPreRequest.cdpRequestWillBeSentTimestamp,
+        cdpRequestWillBeSentReceivedTimestamp: browserPreRequest.cdpRequestWillBeSentReceivedTimestamp,
+        proxyRequestReceivedTimestamp: pendingRequest.proxyRequestReceivedTimestamp,
+        cdpLagDuration: browserPreRequest.cdpRequestWillBeSentReceivedTimestamp - browserPreRequest.cdpRequestWillBeSentTimestamp,
+        proxyRequestCorrelationDuration: Math.max(browserPreRequest.cdpRequestWillBeSentReceivedTimestamp - pendingRequest.proxyRequestReceivedTimestamp, 0),
+      }
+
       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,
+          ...timings,
+        })
+
+        return
+      }
+
+      this.protocolManager?.responseStreamTimedOut({
+        requestId: browserPreRequest.requestId,
+        timings,
+      })
 
       return
     }
 
     debugVerbose('Caching pre-request %s to be matched later. %o', key, browserPreRequest)
     this.pendingPreRequests.push(key, {
       browserPreRequest,
+      cdpRequestWillBeSentTimestamp: browserPreRequest.cdpRequestWillBeSentTimestamp,
+      cdpRequestWillBeSentReceivedTimestamp: browserPreRequest.cdpRequestWillBeSentReceivedTimestamp,
+    })
+  }
+
+  addPendingUrlWithoutPreRequest (url: string) {
+    const key = `GET-${url}`
+    const pendingRequest = this.pendingRequests.shift(key)
+
+    if (pendingRequest) {
+      debugVerbose('Handling %s without a CDP prerequest', key)
+      clearTimeout(pendingRequest.timeout)
+      pendingRequest.callback()
+
+      return
+    }
+
+    this.pendingUrlsWithoutPreRequests.push(key, {
       timestamp: Date.now(),
     })
   }
@@ -143,29 +196,53 @@ 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 pendingUrlWithoutPreRequests = this.pendingUrlsWithoutPreRequests.shift(key)
+
+    if (pendingUrlWithoutPreRequests) {
+      metrics.immediatelyMatchedRequests++
+      ctxDebug('Incoming request %s matches known pending url without pre request', key)
+      callback()
 
       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)
+        ctxDebug('Never received pre-request or url without 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/network-proxy.ts

@@ -17,6 +17,10 @@ export class NetworkProxy {
     this.http.removePendingBrowserPreRequest(requestId)
   }
 
+  addPendingUrlWithoutPreRequest (url: string) {
+    this.http.addPendingUrlWithoutPreRequest(url)
+  }
+
   handleHttpRequest (req, res) {
     const span = telemetry.startSpan({
       name: 'network:proxy:handleHttpRequest',

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
           }),