chore: Refactor assertion logging (#23354)

* chore: Refactor assertion logging

* Remove duplicate snapshot on command failure; Prevent circular json error when inspecting commands

* Fix for 'next' attribute in logs

* Add comments about logging and assertions

* Fix duplicate logs on not.exist assertions

* Move command-merging logic into asserting.ts

* Fix TS error

* Fix race condition with cross-origin tests

* Review updates

Author: Blue F

packages/driver/cypress/e2e/commands/assertions.cy.js

@@ -329,11 +329,15 @@ describe('src/cy/commands/assertions', () => {
       it('resolves eventually not exist', () => {
         const button = cy.$$('button:first')
 
-        cy.on('command:retry', _.after(2, _.once(() => {
+        cy.on('command:retry', _.after(3, _.once(() => {
           button.remove()
         })))
 
         cy.get('button:first').click().should('not.exist')
+
+        cy.then(function () {
+          assertLogLength(this.logs, 3)
+        })
       })
 
       it('resolves all 3 assertions', (done) => {
@@ -715,7 +719,6 @@ describe('src/cy/commands/assertions', () => {
       it('does not log ensureElExistence errors', function (done) {
         cy.on('fail', (err) => {
           assertLogLength(this.logs, 1)
-
           done()
         })
 
@@ -790,19 +793,18 @@ describe('src/cy/commands/assertions', () => {
       cy.noop({}).should('have.property', 'foo')
     })
 
-    it('ends and snapshots immediately and sets child', (done) => {
+    it('snapshots immediately and sets child', (done) => {
       cy.on('log:added', (attrs, log) => {
-        if (attrs.name === 'assert') {
-          cy.removeAllListeners('log:added')
+        if (attrs.name !== 'assert') {
+          return
+        }
 
-          expect(log.get('ended')).to.be.true
-          expect(log.get('state')).to.eq('passed')
-          expect(log.get('snapshots').length).to.eq(1)
-          expect(log.get('snapshots')[0]).to.be.an('object')
-          expect(log.get('type')).to.eq('child')
+        cy.removeAllListeners('log:added')
+        expect(log.get('snapshots').length).to.eq(1)
+        expect(log.get('snapshots')[0]).to.be.an('object')
+        expect(log.get('type')).to.eq('child')
 
-          done()
-        }
+        done()
       })
 
       cy.get('body').then(() => {

packages/driver/src/cy/assertions.ts

@@ -222,9 +222,11 @@ export const create = (Cypress: ICypress, cy: $Cy) => {
     return null
   }
 
-  const finishAssertions = (assertions) => {
-    return _.each(assertions, (log) => {
-      log.snapshot()
+  const finishAssertions = () => {
+    cy.state('current').get('logs').forEach((log) => {
+      if (log.get('next') || !log.get('snapshots')) {
+        log.snapshot()
+      }
 
       const e = log.get('_error')
 
@@ -238,7 +240,6 @@ export const create = (Cypress: ICypress, cy: $Cy) => {
 
   type VerifyUpcomingAssertionsCallbacks = {
     ensureExistenceFor?: 'subject' | 'dom' | boolean
-    onPass?: Function
     onFail?: (err?, isDefaultAssertionErr?: boolean, cmds?: any[]) => void
     onRetry?: () => any
   }
@@ -256,10 +257,6 @@ export const create = (Cypress: ICypress, cy: $Cy) => {
       // case where there are no upcoming assertion commands
       const isDefaultAssertionErr = cmds.length === 0
 
-      if (options.assertions == null) {
-        options.assertions = []
-      }
-
       _.defaults(callbacks, {
         ensureExistenceFor: 'dom',
       })
@@ -296,9 +293,6 @@ export const create = (Cypress: ICypress, cy: $Cy) => {
 
       const onPassFn = () => {
         cy.state('overrideAssert', undefined)
-        if (_.isFunction(callbacks.onPass)) {
-          return callbacks.onPass.call(this, cmds, options.assertions)
-        }
 
         return subject
       }
@@ -342,8 +336,9 @@ export const create = (Cypress: ICypress, cy: $Cy) => {
             onFail.call(this, err, isDefaultAssertionErr, cmds)
           }
         } catch (e3) {
-          finishAssertions(options.assertions)
           throw e3
+        } finally {
+          finishAssertions()
         }
 
         if (_.isFunction(onRetry)) {
@@ -380,108 +375,7 @@ export const create = (Cypress: ICypress, cy: $Cy) => {
         .catch(onFailFn)
       }
 
-      let i = 0
-
-      const cmdHasFunctionArg = (cmd) => {
-        return _.isFunction(cmd.get('args')[0])
-      }
-
       const overrideAssert = function (...args) {
-        let cmd = cmds[i]
-        const setCommandLog = (log) => {
-          // our next log may not be an assertion
-          // due to page events so make sure we wait
-          // until we see page events
-          if (log.get('name') !== 'assert') {
-            return
-          }
-
-          // when we do immediately unbind this function
-          cy.state('onBeforeLog', null)
-
-          const insertNewLog = (log) => {
-            cmd.log(log)
-
-            return options.assertions.push(log)
-          }
-
-          // its possible a single 'should' will assert multiple
-          // things such as the case with have.property. we can
-          // detect when that is happening because cmd will be null.
-          // if thats the case then just set cmd to be the previous
-          // cmd and do not increase 'i'
-          // this will prevent 2 logs from ever showing up but still
-          // provide errors when the 1st assertion fails.
-          if (!cmd) {
-            cmd = cmds[i - 1]
-          } else {
-            i += 1
-          }
-
-          // if our command has a function argument
-          // then we know it may contain multiple
-          // assertions
-          if (cmdHasFunctionArg(cmd)) {
-            let index = cmd.get('assertionIndex')
-            let assertions = cmd.get('assertions')
-
-            // https://github.com/cypress-io/cypress/issues/4981
-            // `assertions` is undefined because assertions added by
-            // `should` command are not handled yet.
-            // So, don't increase i and go back to the last command.
-            if (!assertions) {
-              i -= 1
-              cmd = cmds[i - 1]
-              index = cmd.get('assertionIndex')
-              assertions = cmd.get('assertions')
-            }
-
-            // always increase the assertionIndex
-            // so our next assertion matches up
-            // to the correct index
-            const incrementIndex = () => {
-              return cmd.set('assertionIndex', index += 1)
-            }
-
-            // if we dont have an assertion at this
-            // index then insert a new log
-            const assertion = assertions[index]
-
-            if (!assertion) {
-              assertions.push(log)
-              incrementIndex()
-
-              return insertNewLog(log)
-            }
-
-            // else just merge this log
-            // into the previous assertion log
-            incrementIndex()
-            assertion.merge(log)
-
-            // dont output a new log
-            return false
-          }
-
-          // if we already have a log
-          // then just update its attrs from
-          // the new log
-          const l = cmd.getLastLog()
-
-          if (l) {
-            l.merge(log)
-
-            // and make sure we return false
-            // which prevents a new log from
-            // being added
-            return false
-          }
-
-          return insertNewLog(log)
-        }
-
-        cy.state('onBeforeLog', setCommandLog)
-
         // send verify=true as the last arg
         return assertFn.apply(this, args.concat(true) as any)
       }
@@ -537,7 +431,7 @@ export const create = (Cypress: ICypress, cy: $Cy) => {
 
         setSubjectAndSkip()
 
-        finishAssertions(options.assertions)
+        finishAssertions()
 
         return onPassFn()
       })
@@ -547,7 +441,7 @@ export const create = (Cypress: ICypress, cy: $Cy) => {
         // when we're told not to retry
         if (err.retry === false) {
           // finish the assertions
-          finishAssertions(options.assertions)
+          finishAssertions()
 
           // and then push our command into this err
           try {

packages/driver/src/cy/commands/asserting.ts

@@ -7,6 +7,29 @@ import $errUtils from '../../cypress/error_utils'
 const reExistence = /exist/
 const reHaveLength = /length/
 
+const onBeforeLog = (log, command, commandLogId) => {
+  log.set('commandLogId', commandLogId)
+
+  const previousLogInstance = command.get('logs').find(_.matchesProperty('attributes.commandLogId', commandLogId))
+
+  if (previousLogInstance) {
+    // log.merge unsets any keys that aren't set on the new log instance. We
+    // copy over 'snapshots' beforehand so that existing snapshots aren't lost
+    // in the merge operation.
+    log.set('snapshots', previousLogInstance.get('snapshots'))
+    previousLogInstance.merge(log)
+
+    if (previousLogInstance.get('end')) {
+      previousLogInstance.end()
+    }
+
+    // Returning false prevents this new log from being added to the command log
+    return false
+  }
+
+  return true
+}
+
 export default function (Commands, Cypress, cy, state) {
   const shouldFnWithCallback = function (subject, fn) {
     state('current')?.set('followedByShouldCallback', true)
@@ -24,8 +47,44 @@ export default function (Commands, Cypress, cy, state) {
   }
 
   const shouldFn = function (subject, chainers, ...args) {
+    const command = cy.state('current')
+
+    // Most commands are responsible for creating and managing their own log messages directly.
+    // .should(), however, is an exception - it is invoked by earlier commands, as part of
+    // `verifyUpcomingAssertions`. This callback can also be invoked any number of times, but we only want
+    // to display a few log messages (one for each assertion).
+
+    // Therefore, we each time Cypress.log() is called, we need a way to identify if this log call
+    // a duplicate of a previous one that's just being retried. This is the purpose of `commandLogId` - it should
+    // remain the same across multiple invocations of verifyUpcomingAssertions().
+
+    // It is composed of two parts: assertionIndex and logIndex. Assertion index is "which .should() command are we
+    // inside". Consider the following case:
+    // `cy.noop(3).should('be.lessThan', 4).should('be.greaterThan', 2)`
+    // cy.state('current') is always the 'noop' command, which rolls up the two upcoming assertions, lessThan and
+    // greaterThan. `assertionIndex` lets us tell them apart even though they have the same logIndex of 0 (since it
+    // resets each time .should() is called).
+
+    // As another case, consider:
+    // cy.noop(3).should((n) => { expect(n).to.be.lessThan(4); expect(n).to.be.greaterThan(2); })
+    // Here, assertionIndex is 0 for both - one .should() block generates two log messages. In this case, logIndex is
+    // used to tell them apart, since it increments each time Cypress.log() is called within a single retry of a single
+    // .should().
+    const assertionIndex = cy.state('upcomingAssertions') ? cy.state('upcomingAssertions').indexOf(command.get('currentAssertionCommand')) : 0
+    let logIndex = 0
+
     if (_.isFunction(chainers)) {
-      return shouldFnWithCallback.apply(this, [subject, chainers])
+      cy.state('onBeforeLog', (log) => {
+        logIndex++
+
+        return onBeforeLog(log, command, `${assertionIndex}-${logIndex}`)
+      })
+
+      try {
+        return shouldFnWithCallback.apply(this, [subject, chainers])
+      } finally {
+        cy.state('onBeforeLog', undefined)
+      }
     }
 
     let exp = cy.expect(subject).to
@@ -35,6 +94,7 @@ export default function (Commands, Cypress, cy, state) {
       // since we are throwing our own error
       // without going through the assertion we need
       // to ensure our .should command gets logged
+      logIndex++
       const log = Cypress.log({
         name: 'should',
         type: 'child',
@@ -58,31 +118,40 @@ export default function (Commands, Cypress, cy, state) {
     const isCheckingLengthOrExistence = isCheckingExistence || reHaveLength.test(chainers)
 
     const applyChainer = function (memo, value) {
-      if (value === lastChainer && !isCheckingExistence) {
+      logIndex++
+      cy.state('onBeforeLog', (log) => {
+        return onBeforeLog(log, command, `${assertionIndex}-${logIndex}`)
+      })
+
+      try {
+        if (value === lastChainer && !isCheckingExistence) {
         // https://github.com/cypress-io/cypress/issues/16006
         // Referring some commands like 'visible'  triggers assert function in chai_jquery.js
         // It creates duplicated messages and confuses users.
-        const cmd = memo[value]
-
-        if (_.isFunction(cmd)) {
-          try {
-            return cmd.apply(memo, args)
-          } catch (err: any) {
-            // if we made it all the way to the actual
-            // assertion but its set to retry false then
-            // we need to log out this .should since there
-            // was a problem with the actual assertion syntax
-            if (err.retry === false) {
-              return throwAndLogErr(err)
+          const cmd = memo[value]
+
+          if (_.isFunction(cmd)) {
+            try {
+              return cmd.apply(memo, args)
+            } catch (err: any) {
+              // if we made it all the way to the actual
+              // assertion but its set to retry false then
+              // we need to log out this .should since there
+              // was a problem with the actual assertion syntax
+              if (err.retry === false) {
+                return throwAndLogErr(err)
+              }
+
+              throw err
             }
-
-            throw err
+          } else {
+            return cmd
           }
         } else {
-          return cmd
+          return memo[value]
         }
-      } else {
-        return memo[value]
+      } finally {
+        cy.state('onBeforeLog', undefined)
       }
     }
 

packages/driver/src/cy/commands/waiting.ts

@@ -300,16 +300,16 @@ export default (Commands, Cypress, cy, state) => {
         if (responsesOrErr.hasSpecBridgeError) {
           delete responsesOrErr.hasSpecBridgeError
           if (options.log) {
+            // skip this 'wait' log since it was already added through the primary
             Cypress.state('onBeforeLog', (log) => {
-              // skip this 'wait' log since it was already added through the primary
               if (log.get('name') === 'wait') {
                 // unbind this function so we don't impact any other logs
                 cy.state('onBeforeLog', null)
 
                 return false
               }
 
-              return
+              return true
             })
           }