Cypress tests slow down or fail, UI is unresponsive in 3.3.1

[joydeep100]

Current behavior:

I noticed the some of our API, mainly XHR requests were continuously getting looped indefinitely when i upgraded Cypress from 3.2.0 to 3.3.0. So we rolled it back.
Now we hit some other bugs, for which we wanted to upgrade to Cypress 3.3.1, once again i am getting a similar issue.

1. For some of the tests some XHR requests are loading indefinitely.
2. The Timer is not incrementing
3. The Test Runner is not responding

------------ Configuration -------
{
animationDistanceThreshold: 5,
baseUrl: null,
blacklistHosts: null,
chromeWebSecurity: true,
defaultCommandTimeout: 20000,
env: {
CLIENT: 'demoaccount',
failOnSnapshotDiff: false},
execTimeout: 60000,
fileServerFolder: '',
fixturesFolder: 'cypress/fixtures',
hosts: null,
integrationFolder: 'cypress/integration',
modifyObstructiveCode: true,
numTestsKeptInMemory: 1,
pageLoadTimeout: 60000,
pluginsFile: 'cypress/plugins',
port: null,
reporter: 'spec',
reporterOptions: null,
requestTimeout: 5000,
responseTimeout: 30000,
screenshotsFolder: 'cypress/screenshots',
supportFile: 'cypress/support',
taskTimeout: 60000,
testFiles: '**/*.{spec.js,feature}',
trashAssetsBeforeRuns: true,
userAgent: null,
video: true,
videoCompression: 32,
videoUploadOnPasses: true,
videosFolder: 'cypress/videos',
viewportHeight: 660,
viewportWidth: 1000,
waitForAnimations: true,
watchForFileChanges: true}
-----------

Scenario failing- Validating the time/date picker yields a correct date in the calendar while scheduling email message (we are using cucumber library)

Desired behavior:

Things are fine in 3.2.0, except some known issues like forwarding of socket failures related error in HTTP api level, which causes some parse error (Internal Error 500) in cypress.

Steps to reproduce: (app code and test code)

I am sharing some snippet of the login code, which we use to login.

Cypress.Commands.add(
	'login',
	{
		prevSubject: 'true'
	},
	(client, user) => {
		cy.logout();
		return cy.visit(`${BASE_URL}`).then(() => {
			return cy.getCookie('csrftoken').then(({ value }) => {
				return cy
					.request({
						url: `${client.url}/accounts/login`,
						form: true,
						method: 'POST',
						body: {
							username: client.users[user].email,
							password: client.users[user].password,
							csrfmiddlewaretoken: value
						}
					})
					.then(() => client);
			});
		});
	}
);

Versions

cypress - 3.3.1
electron - 61
OS - Mac OS Mojave 10.14.5

Attachments

cy_3.3.0_debug.log
cy_3.3.1_debug.log

[joydeep100]

One more interesting observation is that, this works fine in Chrome75. This seem to be failing only in Electron browser.

[jennifer-shehane]

@joydeep100 If you're using ServiceWorkers, there's a known issue for this: #1716 (comment)

This issue was opened concerning WebSockets in 3.3.1 also. #4366

Can you narrow down if this is happening in 3.3.0 / 3.3.1 / or both?

And if you can, run Cypress in debug mode mode and print the logs here/

[joydeep100]

Hi @jennifer-shehane , yes the issue is reproducible in cypress-3.3.0 as well. I have attached the debug logs from both the versions.

[abzainuddin]

I'm seeing the same problem. In 3.2.0 everything works fine, but upgrading to 3.3.0 / 3.3.1 some requests seems to get "stuck".

When checking the backend logs, the request is successfully responded, but Cypress seems to miss the response.

Still trying to pinpoint what exactly causes this problem. It seems to only occur with one specific test.

[flotwig]

@abzainuddin Can you share the spec code that reproduces this issue?

[abzainuddin]

This test most of the time doesn't work, once in a while it does work:

it('should be able add success rate to a quotation', () => {
    cy.loadFixture(fixture);
    cy.login('account_manager@codeyellow.nl');
    cy.visit('/orders/project/1/order/1/edit/quotations');

    cy.get('.handshake').click();
    cy.contains('Add').click();
    cy.shouldShowValidationNotification();
    cy.get('[name="rate"]').hasValidationError('Rate must be an integer');

    cy.get('[name="rate"]').type('123');
    cy.contains('Add').click();
    cy.shouldShowValidationNotification();
    cy.get('[name="rate"]').hasValidationError('Rate must be between 0 and 100');

    cy.get('[name="rate"]').type('{selectall}15');
    cy.contains('Add').click(); // Causes infinite pending request, while backend reports done.
    cy.shouldShowSaveNotification();

    cy.contains('15%').should('be.visible');
});

After the test has failed (because of timeout), you do see in the dev console that the request is done:

See also this screencast https://people.codeyellow.nl/burhan/cypress-bug.mp4 (somehow without my mouse, but you get the picture). After a minute or so the request does resolve. I've tested using different browsers, all giving the same result:

[flotwig]

Okay, I was able to sorta reproduce this by writing tests that do a toooon of mocked route request all at once. Eventually Cypress locks up and starts stuttering and shows the symptoms you're experiencing:

Spec code:

const letters = ['a','b','c','d','e','f']

it('should get responses for all XHRs', function() {
  cy.server()
  cy.pause() // just so i can record a video of it before it locks up
  
  letters.forEach(l => {
    cy.route(`**/${l}`, 'it wokred').as(l + 'g')
    cy.route('POST', `**/${l}`, 'it wokred').as(l + 'p')
  })

  cy.visit('/index-xhrs.html')

  letters.forEach(l => {
    cy.wait(`@${l}g`)
    cy.wait(`@${l}p`)
  })
})

/index-xhrs.html:

<script type="text/javascript">
const letters = ['a','b','c','d','e','f']

Cypress._.times(200, (i) => {
  setTimeout(() => {
    const xhr = new XMLHttpRequest
    xhr.open('GET', `http://example.com/${letters[i % letters.length]}`)
    xhr.send()

    const xhr2 = new XMLHttpRequest
    xhr2.open('POST', `http://example.com/${letters[i % letters.length]}`)
    xhr2.send()
  }, Math.random() * 5000)
})
</script>

Running in Electron, you can clearly see Cypress freezing and struggling to keep up: https://drive.google.com/open?id=1wbC5cobVkvJcA0wL0nVlweaEVT5wRzhN

The same thing happens in Chrome. I actually got it to fail the test because an XHR timed out as well. You can also see that Cypress is using 150% CPU as it tries to keep the tests running (well, that part didn't record, but it's true): https://drive.google.com/open?id=1G5kugjCn5A2dq04kKyRHpxudU6fjTHJF

To me, this looks like there's a performance issue here. I'm going to test with some of the performance improvements that will be in 3.3.2 and report back if that fixes it.

EDIT: Doesn't look like this is fixed by the changes that will be going into 3.3.2, looking more into it.

---

EDIT 2: Captured a flamegraph of the performance, looks like we're doing some computation that is causing ticks to take 100's of ms in the browser:

CPU profile JSON: https://drive.google.com/file/d/1XLcngKMDS9X-MkuUTtq-M7L0twPH50mO/view?usp=sharing

Looks like it all comes down to logFn being called a lot, which causes a lot of re-renders with React, causing the browser to lock up:

Maybe we can debounce this or otherwise decrease the number of unnecessary updates to the React components, or trace it back to the actual change between v3.2.0...v3.3.0 that causes this.

---

EDIT 3: Tested in 3.2.0, the stuttering is still there with this test case but it's much less pronounced - the test finishes in <10 seconds.

---

EDIT 4: Followed this fantastic guide to React profiling to get access to React-notated updates: it looks like every Command component is getting updated over and over, leading to the lag:

cypress/packages/reporter/src/commands/command.jsx

Line 85 in c7b340a

class Command extends Component {

Predictably, adding shouldComponentUpdate = () => false to Command fixes the lag - the test case now completes in 3 seconds. So probably just need to refine this component's update mechanism some more.

Probably some change in here: git diff v3.2.0...v3.3.0 -- packages/reporter/**/*.jsx

---

EDIT 5: Added some code to detect prop changes to Collapsible and Command:

  componentDidUpdate (prevProps, prevState) {
    if (this.props.isOpen != null && this.props.isOpen !== prevProps.isOpen) {
      this.setState({ isOpen: this.props.isOpen })
    }

    Object.entries(this.props).forEach(([key, val]) =>
      prevProps[key] !== val && console.log(`${_.uniqueId('CollapsileProp')}  Prop '${key}' changed`)
    )
    Object.entries(this.state).forEach(([key, val]) =>
      prevState[key] !== val && console.log(`${_.uniqueId('CollapsileState')}  State '${key}' changed`)
    )
  }

  componentDidUpdate (prevProps, prevState) {
    prevProps && Object.entries(this.props).forEach(([key, val]) =>
      prevProps[key] !== val && console.log(`${_.uniqueId('CommandProp')} Prop '${key}' changed`)
    )
  }

Using this, discovered that during my test case, Command was re-rendered 86,768 times and Collapsible was re-rendered 86,770 times. Going to try to implement some debouncing logic on updates to alleviate this.

[flotwig]

This slowdown appears to happen with all Cypress commands, @fr0 in #4313 created an example repo (https://github.com/fr0/cypress-slowdown) that shows a 2x slowdown with .get, .click and other commands. I profiled the difference between 3.2.0 and develop and it also comes down re-rendering. It looks like everything under every Command is re-rendering over and over:

Sample call tree of one update of Tree from 3.2.0:

For comparison, sample call tree of one update of Tree from latest develop:

Command.shouldComponentUpdate looks like the root of the slowdown, it's no longer returning false when it should and so everything re-renders on every change to Test's state or props.

[fr0]

Since it was introduced in 3.3.0, it might help to do a git bisect to narrow down the exact commit that introduced the issue.

[fr0]

Not sure if this is useful information or not, but I just tried my test case with --browser chrome and the slowdown occurred, which seems to contradict the earlier comment that "this works fine in Chrome75. This seem to be failing only in Electron browser."

[flotwig]

Yeah, it happens in both Chromium 75 and Electron for me too. It's possible that it's less pronounced in Chrome for some reason.

[flotwig]

Thanks for reminding me that git bisect exists. ;) Tracked it down to #3188, which isn't a lot of changes, picking through it now.

[cypress-bot]

The code for this is done in cypress-io/cypress#4552, but has yet to be released.
We'll update this issue and reference the changelog when it's released.

[fr0]

Nice! Thanks for your hard work. I verified that the latest build does, in fact, fix my issue. Looking forward to 3.3.2!

[cypress-bot]

Released in 3.3.2.

[joydeep100]

Hello @flotwig @jennifer-shehane

I just wanted to verify that the issue is closed. Hence during my re-testing with version 3.3.2 i can see the same issue is occurring again and i confirm that this occurs only in electron.

One of the calls that (XHR) that kept looping was mark_as/ . I am attaching a HAR dump file for the network requests during the test. I hope that would be useful.

cypress.har.txt

p.s. Please rename cypress.har.txt to cypress.har if your HAR analyser needs that.

[jennifer-shehane]

@joydeep100 Yes, this issue was intended to be completely fixed in version 3.3.2.

@flotwig can you take a look at the HAR file?

[joydeep100]

Hi @flotwig , Just curious to know if you were able to corner the issue.

[kris4345]

I got this thank you

…

On Mon, 8 Jul. 2019, 5:10 pm joydeep, ***@***.***> wrote: Hi @flotwig <https://github.com/flotwig> , Just curious to know if you were able to corner the issue. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#4411?email_source=notifications&email_token=ADCJTW3Z52KIN6WNXNLDEQDP6LR6JA5CNFSM4HVXLJSKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODZMFV7Y#issuecomment-509106943>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ADCJTW5OWOFHLH5PWDHVSHLP6LR6JANCNFSM4HVXLJSA> .

[flotwig]

@joydeep100 Let's move discussion of this issue to #4668, since the history of this issue has become about something else. I thought we fixed the issue you're experiencing in 3.3.2, but apparently I reproducing another potential cause of XHR flakiness all along 😛