chore: add telemetry to the proxy (#26695)

* chore: set up instrumentation and instrument middleware * chore: set up console exporter * chore: add parent span option to telemetry package * chore: set up telemetry verbose mode * chore: instrument the network proxy - part 1 * chore: make sure to terminate spans when request is aborted * fix telemetry, create/end the request middle prior to sending the outbound request * avoid telemetry ts build step, create entrypoint into packages/telemetry using TS conventions * allow env vars to be "true" or "1" * when creating child span, inherit their attributes directly from the parent * create custom honeycomb exporter and span processor to log traces * remove duplicate code that's already called in this.setRootContext * cleanup * more clean up * update honeycomb network:proxy attributes, update console.log message * yarn lock * chore: remove performance API in middleware * chore: end response on correct event * recursively gather parent attributes on close * added key and some clean up * github action detector, move verbose into index, verbose log commands * some tests * clean up honeycomb exporter * some renaming * testing console trace link exporter * Don't lose the top span when running in verbose. * link to the right place for prod/dev * changes to verbose to make sure it is read in the browser * Apply suggestions from code review * pass parent attributes between telemetry instances * default to false * 'fix' build issues * src not dist * add back on start span * once more with feeling * Fix some tests * try this i guess * revert auto build * Apply suggestions from code review Co-authored-by: Bill Glesias <[email protected]> * support failed commands * Address PR comments * Address PR Comments * error handling * handle all the errors --------- Co-authored-by: Bill Glesias <[email protected]> Co-authored-by: Brian Mann <[email protected]>
cypress-io · May 17, 2023 · 50ffd5e · 50ffd5e · cypress-bot · May 17, 2023
1 parent 55bcd2d
commit 50ffd5e
Show file tree

Hide file tree

Showing 29 changed files with 1,154 additions and 116 deletions.
diff --git a/packages/app/src/runner/events/telemetry.ts b/packages/app/src/runner/events/telemetry.ts
@@ -36,4 +36,69 @@ export const addTelemetryListeners = (Cypress) => {
       // TODO: log error when client side debug logging is available
     }
   })
+
+  const commandSpanInfo = (command: Cypress.CommandQueue) => {
+    const runnable = Cypress.state('runnable')
+    const runnableType = runnable.type === 'hook' ? runnable.hookName : runnable.type
+
+    return {
+      name: `${runnableType}: ${command.attributes.name}(${command.attributes.args.join(',')})`,
+      runnable,
+      runnableType,
+    }
+  }
+
+  Cypress.on('command:start', (command: Cypress.CommandQueue) => {
+    try {
+      const test = Cypress.state('test')
+
+      const { name, runnable, runnableType } = commandSpanInfo(command)
+
+      const span = telemetry.startSpan({
+        name,
+        opts: {
+          attributes: {
+            spec: runnable.invocationDetails.relativeFile,
+            test: `test:${test.fullTitle()}`,
+            'runnable-type': runnableType,
+          },
+        },
+        isVerbose: true,
+      })
+
+      span?.setAttribute('command-name', command.attributes.name)
+    } catch (error) {
+    // TODO: log error when client side debug logging is available
+    }
+  })
+
+  const onCommandEnd = (command: Cypress.CommandQueue) => {
+    try {
+      const span = telemetry.getSpan(commandSpanInfo(command).name)
+
+      span?.setAttribute('state', command.state)
+      span?.setAttribute('numLogs', command.logs?.length || 0)
+      span?.end()
+    } catch (error) {
+    // TODO: log error when client side debug logging is available
+    }
+  }
+
+  Cypress.on('command:end', onCommandEnd)
+
+  Cypress.on('skipped:command:end', onCommandEnd)
+
+  Cypress.on('command:failed', (command: Cypress.CommandQueue, error: Error) => {
+    try {
+      const span = telemetry.getSpan(commandSpanInfo(command).name)
+
+      span?.setAttribute('state', command.state)
+      span?.setAttribute('numLogs', command.logs?.length || 0)
+      span?.setAttribute('error.name', error.name)
+      span?.setAttribute('error.message', error.message)
+      span?.end()
+    } catch (error) {
+    // TODO: log error when client side debug logging is available
+    }
+  })
 }
diff --git a/packages/data-context/src/sources/HtmlDataSource.ts b/packages/data-context/src/sources/HtmlDataSource.ts
@@ -120,7 +120,7 @@ export class HtmlDataSource {
           window.__CYPRESS_CONFIG__ = ${JSON.stringify(serveConfig)};
           window.__CYPRESS_TESTING_TYPE__ = '${this.ctx.coreData.currentTestingType}'
           window.__CYPRESS_BROWSER__ = ${JSON.stringify(this.ctx.coreData.activeBrowser)}
-          ${telemetry.isEnabled() ? `window.__CYPRESS_TELEMETRY__ = ${JSON.stringify({ context: telemetry.getActiveContextObject(), resources: telemetry.getResources() })}` : ''}
+          ${telemetry.isEnabled() ? `window.__CYPRESS_TELEMETRY__ = ${JSON.stringify({ context: telemetry.getActiveContextObject(), resources: telemetry.getResources(), isVerbose: telemetry.isVerbose() })}` : ''}
           ${process.env.CYPRESS_INTERNAL_GQL_NO_SOCKET ? `window.__CYPRESS_GQL_NO_SOCKET__ = 'true';` : ''}
         </script>
     `)

diff --git a/packages/driver/src/cypress.ts b/packages/driver/src/cypress.ts
@@ -616,6 +616,9 @@ class $Cypress {
       case 'cy:command:end':
         return this.emit('command:end', ...args)
 
+      case 'cy:command:failed':
+        return this.emit('command:failed', ...args)
+
       case 'cy:skipped:command:end':
         return this.emit('skipped:command:end', ...args)
 

diff --git a/packages/driver/src/cypress/command_queue.ts b/packages/driver/src/cypress/command_queue.ts
@@ -541,6 +541,7 @@ export class CommandQueue extends Queue<$Command> {
         current.fail()
       }
 
+      Cypress.action('cy:command:failed', current, err)
       this.cleanup()
 
       return this.cy.fail(err)

diff --git a/packages/net-stubbing/lib/server/middleware/request.ts b/packages/net-stubbing/lib/server/middleware/request.ts
@@ -18,13 +18,16 @@ import {
   getBodyEncoding,
 } from '../util'
 import { InterceptedRequest } from '../intercepted-request'
+import { telemetry } from '@packages/telemetry'
 
 // 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 const SetMatchingRoutes: RequestMiddleware = async function () {
+  const span = telemetry.startSpan({ name: 'set:matching:routes', parentSpan: this.reqMiddlewareSpan, isVerbose: true })
+
   if (matchesRoutePreflight(this.netStubbingState.routes, this.req)) {
     // send positive CORS preflight response
     return sendStaticResponse(this, {
@@ -41,15 +44,20 @@ export const SetMatchingRoutes: RequestMiddleware = async function () {
 
   this.req.matchingRoutes = [...getRoutesForRequest(this.netStubbingState.routes, this.req)]
 
+  span?.end()
   this.next()
 }
 
 /**
  * Called when a new request is received in the proxy layer.
  */
 export const InterceptRequest: RequestMiddleware = async function () {
+  const span = telemetry.startSpan({ name: 'intercept:request', parentSpan: this.reqMiddlewareSpan, isVerbose: true })
+
   if (!this.req.matchingRoutes?.length) {
     // not intercepted, carry on normally...
+    span?.end()
+
     return this.next()
   }
 
@@ -166,8 +174,12 @@ export const InterceptRequest: RequestMiddleware = async function () {
   if (request.responseSent) {
     // request has been fulfilled with a response already, do not send the request outgoing
     // @see https://github.com/cypress-io/cypress/issues/15841
+    span?.end()
+
     return this.end()
   }
 
+  span?.end()
+
   return request.continueRequest()
 }
diff --git a/packages/net-stubbing/lib/server/middleware/response.ts b/packages/net-stubbing/lib/server/middleware/response.ts
@@ -3,7 +3,6 @@ import { concatStream, httpUtils } from '@packages/network'
 import Debug from 'debug'
 import type { Readable } from 'stream'
 import { getEncoding } from 'istextorbinary'
-
 import type {
   ResponseMiddleware,
 } from '@packages/proxy'

diff --git a/packages/proxy/lib/http/index.ts b/packages/proxy/lib/http/index.ts
@@ -1,35 +1,41 @@
+import Bluebird from 'bluebird'
+import chalk from 'chalk'
+import Debug from 'debug'
 import _ from 'lodash'
+import { errorUtils } from '@packages/errors'
+import { DeferredSourceMapCache } from '@packages/rewriter'
+import { telemetry, Span } from '@packages/telemetry'
+import ErrorMiddleware from './error-middleware'
+import RequestMiddleware from './request-middleware'
+import ResponseMiddleware from './response-middleware'
+import { HttpBuffers } from './util/buffers'
+import { GetPreRequestCb, PreRequests } from './util/prerequests'
+
 import type EventEmitter from 'events'
 import type CyServer from '@packages/server'
 import type {
   CypressIncomingRequest,
   CypressOutgoingResponse,
   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'
 import type { IncomingMessage } from 'http'
 import type { NetStubbingState } from '@packages/net-stubbing'
-import Bluebird from 'bluebird'
 import type { Readable } from 'stream'
 import type { Request, Response } from 'express'
-import RequestMiddleware from './request-middleware'
-import ResponseMiddleware from './response-middleware'
-import { DeferredSourceMapCache } from '@packages/rewriter'
 import type { RemoteStates } from '@packages/server/lib/remote_states'
 import type { CookieJar, SerializableAutomationCookie } from '@packages/server/lib/util/cookies'
 import type { RequestedWithAndCredentialManager } from '@packages/server/lib/util/requestedWithAndCredentialManager'
-import { errorUtils } from '@packages/errors'
 
 function getRandomColorFn () {
   return chalk.hex(`#${Number(
     Math.floor(Math.random() * 0xFFFFFF),
   ).toString(16).padStart(6, 'F').toUpperCase()}`)
 }
 
+export const isVerboseTelemetry = true
+
+const isVerbose = isVerboseTelemetry
+
 export const debugVerbose = Debug('cypress-verbose:proxy:http')
 
 export enum HttpStages {
@@ -49,6 +55,9 @@ export type HttpMiddlewareStacks = {
 type HttpMiddlewareCtx<T> = {
   req: CypressIncomingRequest
   res: CypressOutgoingResponse
+  handleHttpRequestSpan?: Span
+  reqMiddlewareSpan?: Span
+  resMiddlewareSpan?: Span
   shouldCorrelatePreRequests: () => boolean
   stage: HttpStages
   debug: Debug.Debugger
@@ -164,6 +173,7 @@ export function _runStage (type: HttpStages, ctx: any, onError: Function) {
 
       function _end (retval?) {
         ctx.res.off('close', onClose)
+
         if (ended) {
           return
         }
@@ -215,6 +225,7 @@ export function _runStage (type: HttpStages, ctx: any, onError: Function) {
         middleware.call(fullCtx)
       } catch (err) {
         err.message = `Internal error while proxying "${ctx.req.method} ${ctx.req.proxiedUrl}" in ${middlewareName}:\n${err.message}`
+
         errorUtils.logError(err)
         fullCtx.onError(err)
       }
@@ -255,7 +266,6 @@ export class Http {
   constructor (opts: ServerCtx & { middleware?: HttpMiddlewareStacks }) {
     this.buffers = new HttpBuffers()
     this.deferredSourceMapCache = new DeferredSourceMapCache(opts.request)
-
     this.config = opts.config
     this.shouldCorrelatePreRequests = opts.shouldCorrelatePreRequests || (() => false)
     this.getFileServerToken = opts.getFileServerToken
@@ -273,7 +283,7 @@ export class Http {
     }
   }
 
-  handle (req: CypressIncomingRequest, res: CypressOutgoingResponse) {
+  handleHttpRequest (req: CypressIncomingRequest, res: CypressOutgoingResponse, handleHttpRequestSpan?: Span) {
     const colorFn = debugVerbose.enabled ? getRandomColorFn() : undefined
     const debugUrl = debugVerbose.enabled ?
       (req.proxiedUrl.length > 80 ? `${req.proxiedUrl.slice(0, 80)}...` : req.proxiedUrl)
@@ -282,6 +292,7 @@ export class Http {
     const ctx: HttpMiddlewareCtx<any> = {
       req,
       res,
+      handleHttpRequestSpan,
       buffers: this.buffers,
       config: this.config,
       shouldCorrelatePreRequests: this.shouldCorrelatePreRequests,
@@ -331,6 +342,14 @@ export class Http {
       return _runStage(HttpStages.Error, ctx, onError)
     }
 
+    // start the span that is responsible for recording the start time of the entire middleware run on the stack
+    // make this span a part of the middleware ctx so we can keep names simple when correlating
+    ctx.reqMiddlewareSpan = telemetry.startSpan({
+      name: 'request:middleware',
+      parentSpan: handleHttpRequestSpan,
+      isVerbose,
+    })
+
     return _runStage(HttpStages.IncomingRequest, ctx, onError)
     .then(() => {
       // If the response has been destroyed after handling the incoming request, it implies the that request was canceled by the browser.
@@ -340,7 +359,17 @@ export class Http {
       }
 
       if (ctx.incomingRes) {
+        // start the span that is responsible for recording the start time of the entire middleware run on the stack
+        ctx.resMiddlewareSpan = telemetry.startSpan({
+          name: 'response:middleware',
+          parentSpan: handleHttpRequestSpan,
+          isVerbose,
+        })
+
         return _runStage(HttpStages.IncomingResponse, ctx, onError)
+        .finally(() => {
+          ctx.resMiddlewareSpan?.end()
+        })
       }
 
       return ctx.debug('Warning: Request was not fulfilled with a response.')