products

Add Timestamps To Cypress

Making debugging failed tests easier by adding timestamps to the information.

Sometimes a test fails due to some API service failing to work. You need to debug the service logs, the first piece of information you need is to know when the failure has happened. This blog post explains how to add the timestamps to different parts of Cypress output.

🎁 You can find the source code for this blog post in the repo bahmutov/todo-graphql-example.

Terminal output

Let's output to the terminal when each test begins and finishes using the plugin file. In the plugin file register new tasks to just print the timestamp of the test

cypress/plugins/index.js
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
module.exports = (on, config) => {
  function getUTC() {
    const now = new Date()
    return now.toISOString()
  }

  on('task', {
    beforeTest(testName) {
      console.log(`=== ${getUTC()} start: ${testName}`)
      // cy.task must return something, cannot return undefined
      return null
    },
    afterTest(testName) {
      console.log(`=== ${getUTC()} end: ${testName}`)
      return null
    },
  })
}

We can execute these tasks around every test by using the global beforeEach and afterEach hooks defined in support file.

cypress/support/index.js
1
2
3
4
5
6
7
beforeEach(() => {
  cy.task('beforeTest', Cypress.currentTest.title)
})

afterEach(() => {
  cy.task('afterTest', Cypress.currentTest.title)
})

Note: we had to create our own tasks because Cypress API only has before:run and before:spec events, thus there is no built-in way to run something before or after every test.

The local terminal shows the UTC dates

The timestamps are printed around the test terminal output

If you are recording to Cypress Dashboard, the timestamps and all the output from the plugin file is captured too.

The Dashboard shows the test timestamps

Screenshot timestamp

When a command or an assertion fails, Cypress takes a screenshot, unless screenshotOnRunFailure: false is set. The screenshot event in the plugin file has the information we need - and it is pretty accurate timestamp of the failure. Let's print it to the terminal:

cypress/plugins/index.js
1
2
3
4
5
6
7
8
9
10
11
12
module.exports = (on, config) => {
  ...
  // https://on.cypress.io/after-screenshot-api
  on('after:screenshot', ({ testFailure, takenAt }) => {
    if (testFailure) {
      // this is a screenshot taken on test failure
      // not a screenshot from the cy.screenshot command
      // takenAt is a UTC string
      console.log(`xxx ${takenAt} error`)
    }
  })
}

Note: the screenshot on failure is only taken in the cypress run mode.

Here is a typical output from a failed test, note that using the screenshot we can pin-point the failure a few hundred milliseconds closer compared to the afterEach hook task.

Printing screenshot takenAt timestamp

Add timestamp to the error message

In the Cypress catalog of events you can find the fail event. We can modify the error message and rethrow it. Since we want every test to have the timestamp in the error message, we place our callback in the support file.

cypress/support/index.js
1
2
3
4
5
6
Cypress.on('fail', (err) => {
  console.error(err)
  const at = new Date().toISOString()
  err.message = at + '\n' + err.message
  throw err
})

The timestamp is going to be present in the Dashboard and in the screenshot.

The timestamp is one the first line of the error message

Command timestamps

Inside a long test, you might want to know when a particular command has run. Cypress events has an event command:start delivered when a command is starting. We can take an advantage of this command to add timestamps for each parent command to avoid spamming the Command Log with excessive logging.

1
2
3
4
5
6
7
8
Cypress.on('command:start', ({ attributes }) => {
  if (attributes.type === 'parent') {
    const at = new Date().toISOString()
    Cypress.log({
      name: `${at} - ${attributes.name}`,
    })
  }
})

Printing timestamp at the start of each Cypress command chain

Now we know what is going on and when it is happening!

Note: we cannot simply use cy.log inside the command:start callback since cy.log is itself a command, which will trigger another command:start event, which will just keep looping until the browser runs out of memory.

cypress-timestamps plugin

I factored out the timestamp code into its own plugin cypress-timestamps. Add this plugin as a dev dependency using npm i -D cypress-timestamps and call the registration functions from the support and the plugin files

cypress/support/index.js
1
2
3
4
5
6
// https://github.com/bahmutov/cypress-timestamps
require('cypress-timestamps/support')({
  terminal: true, // by default the terminal output is disabled
  error: true,
  commandLog: true,
})
cypress/plugin/index.js
1
2
3
4
module.exports = (on, config) => {
  // https://github.com/bahmutov/cypress-timestamps
  require('cypress-timestamps/plugin')(on)
}

See also