chore(proxy): improve debug log experience (#21489)

packages/proxy/README.md

@@ -29,3 +29,9 @@ yarn workspace @packages/proxy test
 ```
 
 Additionally, the `server` package contains tests that use the `proxy`.
+
+## Debug Logs
+
+High level logs are available in the `DEBUG=cypress:proxy:*` namespace.
+
+Detailed per-request logs are available in `DEBUG=cypress-verbose:proxy:http`.

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

@@ -1,11 +1,14 @@
-import debugModule from 'debug'
 import * as errors from '@packages/server/lib/errors'
 
 import type { HttpMiddleware } from '.'
 import type { Readable } from 'stream'
 import { InterceptError } from '@packages/net-stubbing'
 import type { Request } from '@cypress/request'
-const debug = debugModule('cypress:proxy:http:error-middleware')
+
+// do not use a debug namespace in this file - use the per-request `this.debug` instead
+// available as cypress-verbose:proxy:http
+// eslint-disable-next-line @typescript-eslint/no-unused-vars
+const debug = null
 
 export type ErrorMiddleware = HttpMiddleware<{
   error: Error
@@ -14,7 +17,7 @@ export type ErrorMiddleware = HttpMiddleware<{
 }>
 
 const LogError: ErrorMiddleware = function () {
-  debug('error proxying request %o', {
+  this.debug('error proxying request %o', {
     error: this.error,
     url: this.req.url,
     headers: this.req.headers,
@@ -36,7 +39,7 @@ const SendToDriver: ErrorMiddleware = function () {
 
 export const AbortRequest: ErrorMiddleware = function () {
   if (this.outgoingReq) {
-    debug('aborting outgoingReq')
+    this.debug('aborting outgoingReq')
     this.outgoingReq.abort()
   }
 
@@ -45,7 +48,7 @@ export const AbortRequest: ErrorMiddleware = function () {
 
 export const UnpipeResponse: ErrorMiddleware = function () {
   if (this.incomingResStream) {
-    debug('unpiping resStream from response')
+    this.debug('unpiping resStream from response')
     this.incomingResStream.unpipe()
   }
 

packages/proxy/lib/http/index.ts

@@ -7,6 +7,7 @@ import type {
   BrowserPreRequest,
 } from '@packages/proxy'
 import Debug from 'debug'
+import chalk from 'chalk'
 import ErrorMiddleware from './error-middleware'
 import { HttpBuffers } from './util/buffers'
 import { GetPreRequestCb, PreRequests } from './util/prerequests'
@@ -21,6 +22,12 @@ import { DeferredSourceMapCache } from '@packages/rewriter'
 import type { Browser } from '@packages/server/lib/browsers/types'
 import type { RemoteStates } from '@packages/server/lib/remote_states'
 
+function getRandomColorFn () {
+  return chalk.hex(`#${Number(
+    Math.floor(Math.random() * 0xFFFFFF),
+  ).toString(16).padStart(6, 'F').toUpperCase()}`)
+}
+
 export const debugVerbose = Debug('cypress-verbose:proxy:http')
 
 export enum HttpStages {
@@ -231,7 +238,12 @@ export class Http {
     }
   }
 
-  handle (req: Request, res: Response) {
+  handle (req: CypressIncomingRequest, res: CypressOutgoingResponse) {
+    const colorFn = debugVerbose.enabled ? getRandomColorFn() : undefined
+    const debugUrl = debugVerbose.enabled ?
+      (req.proxiedUrl.length > 80 ? `${req.proxiedUrl.slice(0, 80)}...` : req.proxiedUrl)
+      : undefined
+
     const ctx: HttpMiddlewareCtx<any> = {
       req,
       res,
@@ -247,7 +259,9 @@ export class Http {
       socket: this.socket,
       serverBus: this.serverBus,
       debug: (formatter, ...args) => {
-        debugVerbose(`%s %s %s ${formatter}`, ctx.req.method, ctx.req.proxiedUrl, ctx.stage, ...args)
+        if (!debugVerbose.enabled) return
+
+        debugVerbose(`${colorFn!(`%s %s`)} %s ${formatter}`, req.method, debugUrl, chalk.grey(ctx.stage), ...args)
       },
       deferSourceMapRewrite: (opts) => {
         this.deferredSourceMapCache.defer({

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

@@ -1,17 +1,19 @@
 import _ from 'lodash'
 import { blocked, cors } from '@packages/network'
 import { InterceptRequest } from '@packages/net-stubbing'
-import debugModule from 'debug'
 import type { HttpMiddleware } from './'
 
+// do not use a debug namespace in this file - use the per-request `this.debug` instead
+// available as cypress-verbose:proxy:http
+// eslint-disable-next-line @typescript-eslint/no-unused-vars
+const debug = null
+
 export type RequestMiddleware = HttpMiddleware<{
   outgoingReq: any
 }>
 
-const debug = debugModule('cypress:proxy:http:request-middleware')
-
 const LogRequest: RequestMiddleware = function () {
-  debug('proxying request %o', {
+  this.debug('proxying request %o', {
     req: _.pick(this.req, 'method', 'proxiedUrl', 'headers'),
   })
 

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

@@ -1,9 +1,9 @@
 import _ from 'lodash'
 import charset from 'charset'
+import type Debug from 'debug'
 import type { CookieOptions } from 'express'
 import { cors, concatStream, httpUtils, uri } from '@packages/network'
 import type { CypressIncomingRequest, CypressOutgoingResponse } from '@packages/proxy'
-import debugModule from 'debug'
 import type { HttpMiddleware, HttpMiddlewareThis } from '.'
 import iconv from 'iconv-lite'
 import type { IncomingMessage, IncomingHttpHeaders } from 'http'
@@ -29,7 +29,10 @@ interface ResponseMiddlewareProps {
 
 export type ResponseMiddleware = HttpMiddleware<ResponseMiddlewareProps>
 
-const debug = debugModule('cypress:proxy:http:response-middleware')
+// do not use a debug namespace in this file - use the per-request `this.debug` instead
+// available as cypress-verbose:proxy:http
+// eslint-disable-next-line @typescript-eslint/no-unused-vars
+const debug = null
 
 // https://github.com/cypress-io/cypress/issues/1756
 const zlibOptions = {
@@ -38,7 +41,7 @@ const zlibOptions = {
 }
 
 // https://github.com/cypress-io/cypress/issues/1543
-function getNodeCharsetFromResponse (headers: IncomingHttpHeaders, body: Buffer) {
+function getNodeCharsetFromResponse (headers: IncomingHttpHeaders, body: Buffer, debug: Debug.Debugger) {
   const httpCharset = (charset(headers, body, 1024) || '').toLowerCase()
 
   debug('inferred charset from response %o', { httpCharset })
@@ -133,7 +136,7 @@ const stringifyFeaturePolicy = (policy: any): string => {
 }
 
 const LogResponse: ResponseMiddleware = function () {
-  debug('received response %o', {
+  this.debug('received response %o', {
     req: _.pick(this.req, 'method', 'proxiedUrl', 'headers'),
     incomingRes: _.pick(this.incomingRes, 'headers', 'statusCode'),
   })
@@ -143,10 +146,10 @@ const LogResponse: ResponseMiddleware = function () {
 
 const AttachPlainTextStreamFn: ResponseMiddleware = function () {
   this.makeResStreamPlainText = function () {
-    debug('ensuring resStream is plaintext')
+    this.debug('ensuring resStream is plaintext')
 
     if (!this.isGunzipped && resIsGzipped(this.incomingRes)) {
-      debug('gunzipping response body')
+      this.debug('gunzipping response body')
 
       const gunzip = zlib.createGunzip(zlibOptions)
 
@@ -193,6 +196,8 @@ const PatchExpressSetHeader: ResponseMiddleware = function () {
 
   let kOutHeaders
 
+  const ctxDebug = this.debug
+
   this.res.setHeader = function (name, value) {
     // express.Response.setHeader does all kinds of silly/nasty stuff to the content-type...
     // but we don't want to change it at all!
@@ -209,7 +214,7 @@ const PatchExpressSetHeader: ResponseMiddleware = function () {
         throw err
       }
 
-      debug('setHeader error ignored %o', { name, value, code: err.code, err })
+      ctxDebug('setHeader error ignored %o', { name, value, code: err.code, err })
 
       if (!kOutHeaders) {
         kOutHeaders = getKOutHeadersSymbol()
@@ -334,7 +339,7 @@ const SetInjectionLevel: ResponseMiddleware = function () {
     || resContentTypeIsJavaScript(this.incomingRes)
   )
 
-  debug('injection levels: %o', _.pick(this.res, 'isInitial', 'wantsInjection', 'wantsSecurityRemoved'))
+  this.debug('injection levels: %o', _.pick(this.res, 'isInitial', 'wantsInjection', 'wantsSecurityRemoved'))
 
   this.next()
 }
@@ -410,20 +415,21 @@ interface EnsureSameSiteNoneProps {
   browser: Browser | { family: string | null }
   isLocalhost: boolean
   url: URL
+  ctxDebug: Debug.Debugger
 }
 
 const cookieSameSiteRegex = /SameSite=(\w+)/i
 const cookieSecureRegex = /(^|\W)Secure(\W|$)/i
 const cookieSecureSemicolonRegex = /;\s*Secure/i
 
-const ensureSameSiteNone = ({ cookie, browser, isLocalhost, url }: EnsureSameSiteNoneProps) => {
-  debug('original cookie: %s', cookie)
+const ensureSameSiteNone = ({ cookie, browser, isLocalhost, url, ctxDebug }: EnsureSameSiteNoneProps) => {
+  ctxDebug('original cookie: %s', cookie)
 
   if (cookieSameSiteRegex.test(cookie)) {
-    debug('change cookie to SameSite=None')
+    ctxDebug('change cookie to SameSite=None')
     cookie = cookie.replace(cookieSameSiteRegex, 'SameSite=None')
   } else {
-    debug('add SameSite=None to cookie')
+    ctxDebug('add SameSite=None to cookie')
     cookie += '; SameSite=None'
   }
 
@@ -439,15 +445,15 @@ const ensureSameSiteNone = ({ cookie, browser, isLocalhost, url }: EnsureSameSit
   // remove Secure from http://localhost cookies in Firefox.
   if (cookieSecureRegex.test(cookie)) {
     if (isFirefox && isLocalhost && url.protocol === 'http:') {
-      debug('remove Secure from cookie')
+      ctxDebug('remove Secure from cookie')
       cookie = cookie.replace(cookieSecureSemicolonRegex, '')
     }
   } else if (!isFirefox || url.protocol === 'https:') {
-    debug('add Secure to cookie')
+    ctxDebug('add Secure to cookie')
     cookie += '; Secure'
   }
 
-  debug('resulting cookie: %s', cookie)
+  ctxDebug('resulting cookie: %s', cookie)
 
   return cookie
 }
@@ -464,17 +470,17 @@ const CopyCookiesFromIncomingRes: ResponseMiddleware = function () {
     const url = new URL(this.req.proxiedUrl)
     const isLocalhost = uri.isLocalhost(url)
 
-    debug('force SameSite=None?', needsCrossOriginHandling)
+    this.debug('force SameSite=None?', needsCrossOriginHandling)
 
     ;([] as string[]).concat(cookies).forEach((cookie) => {
       if (needsCrossOriginHandling) {
-        cookie = ensureSameSiteNone({ cookie, browser, isLocalhost, url })
+        cookie = ensureSameSiteNone({ cookie, browser, isLocalhost, url, ctxDebug: this.debug })
       }
 
       try {
         this.res.append('Set-Cookie', cookie)
       } catch (err) {
-        debug('failed to Set-Cookie, continuing %o', { err, cookie })
+        this.debug('failed to Set-Cookie, continuing %o', { err, cookie })
       }
     })
   }
@@ -495,7 +501,7 @@ const MaybeSendRedirectToClient: ResponseMiddleware = function () {
 
   setInitialCookie(this.res, this.remoteStates.current(), true)
 
-  debug('redirecting to new url %o', { statusCode, newUrl })
+  this.debug('redirecting to new url %o', { statusCode, newUrl })
   this.res.redirect(Number(statusCode), newUrl)
 
   return this.end()
@@ -528,12 +534,13 @@ const MaybeInjectHtml: ResponseMiddleware = function () {
 
   this.skipMiddleware('MaybeRemoveSecurity') // we only want to do one or the other
 
-  debug('injecting into HTML')
+  this.debug('injecting into HTML')
 
   this.makeResStreamPlainText()
 
   this.incomingResStream.pipe(concatStream(async (body) => {
-    const nodeCharset = getNodeCharsetFromResponse(this.incomingRes.headers, body)
+    const nodeCharset = getNodeCharsetFromResponse(this.incomingRes.headers, body, this.debug)
+
     const decodedBody = iconv.decode(body, nodeCharset)
     const injectedBody = await rewriter.html(decodedBody, {
       domainName: cors.getDomainNameFromUrl(this.req.proxiedUrl),
@@ -561,7 +568,7 @@ const MaybeRemoveSecurity: ResponseMiddleware = function () {
     return this.next()
   }
 
-  debug('removing JS framebusting code')
+  this.debug('removing JS framebusting code')
 
   this.makeResStreamPlainText()
 
@@ -578,7 +585,7 @@ const MaybeRemoveSecurity: ResponseMiddleware = function () {
 
 const GzipBody: ResponseMiddleware = function () {
   if (this.isGunzipped) {
-    debug('regzipping response body')
+    this.debug('regzipping response body')
     this.incomingResStream = this.incomingResStream.pipe(zlib.createGzip(zlibOptions)).on('error', this.onError)
   }
 

packages/proxy/package.json

@@ -14,6 +14,7 @@
   },
   "dependencies": {
     "bluebird": "3.5.3",
+    "chalk": "2.4.2",
     "charset": "1.0.1",
     "common-tags": "1.8.0",
     "debug": "^4.3.2",

packages/proxy/test/unit/http/index.spec.ts

@@ -44,6 +44,7 @@ describe('http', function () {
       })
 
       return new Http(httpOpts)
+      // @ts-ignore
       .handle({}, {})
       .then(function () {
         expect(incomingRequest, 'incomingRequest').to.be.calledOnce
@@ -61,6 +62,7 @@ describe('http', function () {
       })
 
       return new Http(httpOpts)
+      // @ts-ignore
       .handle({}, {})
       .then(function () {
         expect(incomingRequest).to.be.calledOnce
@@ -83,6 +85,7 @@ describe('http', function () {
       })
 
       return new Http(httpOpts)
+      // @ts-ignore
       .handle({}, {})
       .then(function () {
         expect(incomingRequest).to.be.calledOnce
@@ -145,6 +148,7 @@ describe('http', function () {
       middleware[HttpStages.Error].push(error2)
 
       return new Http(httpOpts)
+      // @ts-ignore
       .handle({}, {})
       .then(function () {
         [