chore: Refactor assertion logging

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