New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cypress unexpectedly and randomly hangs when running tests in CI #1912

Closed
brandonb927 opened this Issue Jun 9, 2018 · 20 comments

Comments

@brandonb927

brandonb927 commented Jun 9, 2018

Current behavior:

We have tests running in Jenkins using docker and docker-compose for running micro-services. Many containers spin up and one is used for our app UI, but these are not the problem.

Since upgrading to Cypress 3.0.1, we've been noticing that random builds just stall out and never complete. As a result of this we've had to instate a 30minute timeout on Jenkins jobs. There are no errors visible in the console output so its hard to see what is happening. The exact same codebase, less some changes to upgrade to Cypress 3, worked on Cypress 2.1.0 perfectly fine up until we upgraded. Like this issue, it will run an random number of specs and stall. Everything runs fine using the headed mode, it seems to only affect headless mode.

Below is some log output from invoking Cypress with DEBUG=cypress:* ./node_modules/.bin/cypress run --env configFile=ci --reporter mocha-multi-reporters --reporter-options configFile=cypress/config/reporters.json

[... everything is great up until this point]

  Running: test_spec.js...                               (16 of 16) 
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:run about to run spec { spec: { name: 'test_spec.js', path: 'cypress/integration/test_spec.js', absolute: '/tests/cypress/integration/test_spec.js' }, headed: undefined, browserName: 'electron' }
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:video ffmpeg started
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:project launching browser electron spec /tests/cypress/integration/test_spec.js
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:project resetting project instance /tests
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:server Setting remoteAuth undefined
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:cors Parsed URL { port: '15901', tld: 'localhost', domain: '' }
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:server Setting remoteOrigin http://localhost:15901
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:server Setting remoteHostAndPort { port: '15901', tld: 'localhost', domain: '' }
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:server Setting remoteDocDomain localhost
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:server Getting remote state: { auth: undefined, props: { port: '15901', tld: 'localhost', domain: '' }, origin: 'http://localhost:15901', strategy: 'http', visiting: false, domainName: 'localhost', fileServer: null }
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:timers queuing timer id 2034 after 30000 ms
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:timers child received timer id 2034
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:project launching project in browser electron
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:browsers opening browser electron
Sat, 09 Jun 2018 00:08:04 GMT cypress:server making saved state from /root/.cache/Cypress/3.0.1/Cypress/resources/app/packages/server
Sat, 09 Jun 2018 00:08:04 GMT cypress:server for project path /tests
Sat, 09 Jun 2018 00:08:04 GMT cypress:server state path for project /tests
Sat, 09 Jun 2018 00:08:04 GMT cypress:server:appdata path: /root/.config/Cypress/cy/production/projects/tests-7304f32fd2c23aa2ad65c4f536e3c192/state.json
Sat, 09 Jun 2018 00:08:04 GMT cypress:server full state path /root/.config/Cypress/cy/production/projects/tests-7304f32fd2c23aa2ad65c4f536e3c192/state.json
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:file reading JSON file /root/.config/Cypress/cy/production/projects/tests-7304f32fd2c23aa2ad65c4f536e3c192/state.json
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:timers child sending timer id 1468
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:timers child sending timer id 1469
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:timers child sending timer id 1470
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:timers child sending timer id 1471
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:timers child sending timer id 1472
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:timers child sending timer id 1473
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:timers child sending timer id 1474
Sat, 09 Jun 2018 00:08:05 GMT cypress:server:timers child sending timer id 1475

[... repeats a few hundred timer ids then just stops]

Desired behavior:

All tests to run and output correct information regardless of fail or passing

Steps to reproduce:

It's bizarre, I'm not quite sure how to reproduce it reliably as it seems completely random, and only happens about 30% of the time.

NOTE: I cannot recreate a reproducible test case with https://github.com/cypress-io/cypress-test-tiny as it just passes ever single run using Jenkins.

Versions

Cypress 3.0.1 + cypress/base:10 docker image
Jenkins 2.89.3

@brian-mann

This comment has been minimized.

Member

brian-mann commented Jun 16, 2018

Thank you for posting your logs. This is very helpful.

@brian-mann

This comment has been minimized.

Member

brian-mann commented Jun 29, 2018

Released in 3.0.2.

@brandonb927

This comment has been minimized.

brandonb927 commented Jul 3, 2018

Thank you so much for this release @brian-mann! You folks are doing amazing work and I'll always be a crazy supporter of this project

<3 from the @sendwithus team

@ikornienko

This comment has been minimized.

ikornienko commented Jul 6, 2018

We still see this issue happening to our builds with 3.0.2 release (same as for the author of this issue, it started to happen only after upgrading to 3.0.1), the debug output (with file paths being changed / obfuscated):

  Running: test.spec.js...                                                              (9 of 10) 
  cypress:server:run about to run spec { spec: { name: 'test.spec.js', relative: 'cypress/integration/test.spec.js', absolute: '/my-project/cypress/integration/test.spec.js' }, isHeadless: true, browserName: 'electron' } +31ms
  cypress:server:video capture started { command: 'ffmpeg -n 20 /home/circleci/.cache/Cypress/3.0.2/Cypress/resources/app/packages/server/node_modules/@ffmpeg-installer/linux-x64/ffmpeg -f image2pipe -use_wallclock_as_timestamps 1 -i pipe:0 -y -vcodec libx264 -preset ultrafast /my-project/cypress/videos/test.spec.js.mp4' } +13ms
  cypress:server:openproject resetting project state, preparing to launch browser +0ms
  cypress:server:project resetting project instance /my-project +1ms
  cypress:server:server Setting remoteAuth undefined +0ms
  cypress:server:cors Parsed URL { port: '8000', tld: 'localhost', domain: '' } +0ms
  cypress:server:server Setting remoteOrigin https://localhost:8000 +0ms
  cypress:server:server Setting remoteHostAndPort { port: '8000', tld: 'localhost', domain: '' } +0ms
  cypress:server:server Setting remoteDocDomain localhost +0ms
  cypress:server:server Getting remote state: { auth: undefined, props: { port: '8000', tld: 'localhost', domain: '' }, origin: 'https://localhost:8000', strategy: 'http', visiting: false, domainName: 'localhost', fileServer: null } +0ms
  cypress:server:timers queuing timer id 1307 after 30000 ms +1ms
  cypress:server:timers child received timer id 1307 +129ms
  cypress:server:openproject launching browser: electron, spec: cypress/integration/test.spec.js +2ms
  cypress:server:browsers opening browser electron +0ms
  cypress:server:saved_state noop saved state +0ms
  cypress:server:video capture stderr log { message: 'ffmpeg version N-45896-g19c3df0cd-static https://johnvansickle.com/ffmpeg/  Copyright (c) 2000-2018 the FFmpeg developers' } +1ms
  cypress:server:video capture stderr log { message: '  built with gcc 6.3.0 (Debian 6.3.0-18+deb9u1) 20170516' } +0ms
  cypress:server:video capture stderr log { message: '  configuration: --enable-gpl --enable-version3 --enable-static --disable-debug --disable-ffplay --disable-indev=sndio --disable-outdev=sndio --cc=gcc-6 --enable-fontconfig --enable-frei0r --enable-gnutls --enable-gray --enable-libaom --enable-libfribidi --enable-libass --enable-libvmaf --enable-libfreetype --enable-libmp3lame --enable-libopencore-amrnb --enable-libopencore-amrwb --enable-libopenjpeg --enable-librubberband --enable-libsoxr --enable-libspeex --enable-libvorbis --enable-libopus --enable-libtheora --enable-libvidstab --enable-libvo-amrwbenc --enable-libvpx --enable-libwebp --enable-libx264 --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzimg' } +0ms
  cypress:server:video capture stderr log { message: '  libavutil      56. 17.100 / 56. 17.100' } +0ms
  cypress:server:video capture stderr log { message: '  libavcodec     58. 19.100 / 58. 19.100' } +0ms
  cypress:server:video capture stderr log { message: '  libavformat    58. 13.100 / 58. 13.100' } +0ms
  cypress:server:video capture stderr log { message: '  libavdevice    58.  4.100 / 58.  4.100' } +1ms
  cypress:server:video capture stderr log { message: '  libavfilter     7. 20.100 /  7. 20.100' } +0ms
  cypress:server:video capture stderr log { message: '  libswscale      5.  2.100 /  5.  2.100' } +0ms
  cypress:server:video capture stderr log { message: '  libswresample   3.  2.100 /  3.  2.100' } +0ms
  cypress:server:video capture stderr log { message: '  libpostproc    55.  2.100 / 55.  2.100' } +0ms
  cypress:server:timers child sending timer id 578 +134ms
  cypress:server:timers child sending timer id 579 +18ms
  cypress:server:timers child sending timer id 580 +21ms
  cypress:server:timers child sending timer id 581 +5ms
  cypress:server:timers child sending timer id 582 +38ms
  cypress:server:timers child sending timer id 583 +1ms
  cypress:server:timers child sending timer id 584 +0ms
  cypress:server:timers child sending timer id 585 +2ms
  cypress:server:timers child sending timer id 585 +2ms
  cypress:server:timers child sending timer id 586 +9ms
  cypress:server:timers child sending timer id 1090 +42ms
  cypress:server:timers child sending timer id 587 +35ms
  cypress:server:timers child sending timer id 1091 +422ms
  cypress:server:timers child sending timer id 1099 +588ms
  cypress:server:timers child sending timer id 1100 +174ms
  cypress:server:timers child sending timer id 596 +95ms

[ this goes for 100-200 hundred times with different timer ids and ms, until eventually it starts to increment timer id ]

 cypress:server:timers child sending timer id 912 +5s
  cypress:server:timers child sending timer id 913 +37ms
  cypress:server:timers child sending timer id 914 +27ms
  cypress:server:timers child sending timer id 915 +0ms
  cypress:server:timers child sending timer id 916 +1ms

[ and then it increments timer id with various time in ms until the last line ]

  cypress:server:timers child sending timer id 1305 +5ms

And then it stops, and the build is killed by CircleCI with "Too long with no output (exceeded 10m0s)". Same as for the author of this issue, it's not obvious how to reproduce it, sometimes it hangs, sometimes it doesn't.

@brian-mann @jennifer-shehane do you want to reopen this issue, or should it be a new one?

@kamituel

This comment has been minimized.

kamituel commented Jul 6, 2018

@ikornienko The log you provided seems to suggest it's the very same issue we're still having on 3.0.2. I described it here and here.

@brandonb927

This comment has been minimized.

brandonb927 commented Jul 6, 2018

I haven't had time to post back here after running some tests on 3.0.2 but it still seems we're seeing the original issue I was describing in 3.0.1 as well in 3.0.2.

@brian-mann

This comment has been minimized.

Member

brian-mann commented Jul 6, 2018

@brandonb927 @kamituel @ikornienko We've investigated this - and we're still unsure where this could be happening. We fixed the state stuff in 3.0.2 and we've added more debugging logs all around this area.

Currently we we cannot reproduce this locally or in CI, so we'll release 3.0.3 with more debug logs. Once you guys upgrade please post your updated logs here so we can help pinpoint the exact area that it's hanging.

@kristiehowboutdat

This comment has been minimized.

kristiehowboutdat commented Jul 10, 2018

FWIW, we're having the same issue on Buildkite, with docker containers as well (cypress/base:8), and always on the 8th test file, even if the contents are empty.

Using 3.0.2, we have:

working test

  cypress:server:saved_state noop saved state +0ms
  cypress:server:timers queuing timer id 476 after 30000 ms +3ms
  cypress:server:timers child received timer id 476 +3ms
  cypress:server:browsers:electron launching browser window to url  ...

not working test

  cypress:server:openproject launching browser: electron, spec: cypress/integration/08_empty_test.js +1ms
  cypress:server:browsers opening browser electron +0ms
  cypress:server:saved_state noop saved state +0ms
  cypress:server:timers queuing timer id 546 after 30000 ms +3ms
  cypress:server:timers child received timer id 546 +4ms
  cypress:server:timers child sending timer id 395 +1s
  cypress:server:timers child sending timer id 396 +2ms
  cypress:server:timers child sending timer id 417 +2s
  cypress:server:timers child sending timer id 418 +38ms

I will also try and update logs with 3.0.3.

@agualis

This comment has been minimized.

agualis commented Aug 7, 2018

We are also having random errors in travis CI (with cypress 3.0.3). This is the last part of the trace (including the last successful test and the one that never ends):

(Results)
  ┌─────────────────────────���───────────┐
  │ Tests:        1                     │
  │ Passing:      1                     │
  │ Failing:      0                     │
  │ Pending:      0                     │
  │ Skipped:      0                     │
  │ Screenshots:  0                     │
  │ Video:        false                 │
  │ Duration:     5 seconds             │
  │ Spec Ran:     others/login.espec.js │
  └─────────────────────────────────────┘
  cypress:server:run attempting to close the browser +29ms
  cypress:server:browsers killing browser process +1ms
  cypress:server:proxy received response for { url: 'http://localhost:8000/graphql', headers: { date: 'Tue, 07 Aug 2018 14:30:27 GMT', server: 'WSGIServer/0.2 CPython/3.6.5', 'content-type': 'application/json', vary: 'Accept, Accept-Language, Cookie', allow: 'POST, OPTIONS', 'x-frame-options': 'SAMEORIGIN', 'content-language': 'en', 'content-length': '158', 'access-control-allow-origin': '*' }, statusCode: 200, isGzipped: undefined, wantsInjection: false, wantsSecurityRemoved: false } +17ms
  cypress:server:browsers:electron closed event fired +46ms
  cypress:server:preprocessor removeFile /home/travis/build/sennder/octopus/cypress/integration/others/login.espec.js +0ms
  cypress:server:preprocessor base emitter plugin close event +0ms
  cypress:webpack close /home/travis/build/sennder/octopus/cypress/integration/others/login.espec.js +5s
  cypress:server:preprocessor base emitter native close event +1ms
  cypress:server:browsers browser process killed +0ms
  cypress:server:run spec results { stats: { suites: 1, tests: 1, passes: 1, pending: 0, skipped: 0, failures: 0, wallClockStartedAt: 2018-08-07T14:30:22.616Z, wallClockEndedAt: 2018-08-07T14:30:27.702Z, wallClockDuration: 5086 }, reporter: 'spec', reporterStats: { suites: 1, tests: 1, passes: 1, pending: 0, failures: 0, start: 2018-08-07T14:30:22.633Z, end: 2018-08-07T14:30:27.820Z, duration: 5187 }, hooks: [], tests: [ { testId: 'r3', title: [Array], state: 'passed', body: 'function () {\n    Object(__WEBPACK_IMPORTED_MODULE_0__common_login__["a" /* login */])()\n  }', stack: null, error: null, timings: [Object], failedFromHookId: null, wallClockStartedAt: 2018-08-07T14:30:22.660Z, wallClockDuration: 5034, videoTimestamp: null } ], error: null, video: null, screenshots: [], spec: { name: 'others/login.espec.js', relative: 'cypress/integration/others/login.espec.js', absolute: '/home/travis/build/sennder/octopus/cypress/integration/others/login.espec.js' }, shouldUploadVideo: true } +10ms
  cypress:server:timers child sending timer id 199 +2s
  cypress:server:timers child sending timer id 364 +573ms
 ...
  cypress:server:timers child sending timer id 411 +218ms
  cypress:server:timers child sending timer id 412 +156ms
────────────────────────────────────────────────────────────────────────────────────────────────────
                                                                                                    
  Running: stages/dispatching-stage.espec.js...                                           (8 of 10) 
  cypress:server:run about to run spec { spec: { name: 'stages/dispatching-stage.espec.js', relative: 'cypress/integration/stages/dispatching-stage.espec.js', absolute: '/home/travis/build/sennder/octopus/cypress/integration/stages/dispatching-stage.espec.js' }, isHeadless: false, browserName: 'electron' } +10s
  cypress:server:openproject resetting project state, preparing to launch browser +3ms
  cypress:server:project resetting project instance /home/travis/build/sennder/octopus +0ms
  cypress:server:server Setting remoteAuth undefined +0ms
  cypress:server:cors Parsed URL { port: '8002', tld: 'localhost', domain: '' } +1ms
  cypress:server:server Setting remoteOrigin http://localhost:8002 +0ms
  cypress:server:server Setting remoteHostAndPort { port: '8002', tld: 'localhost', domain: '' } +0ms
  cypress:server:server Setting remoteDocDomain localhost +0ms
  cypress:server:server Getting remote state: { auth: undefined, props: { port: '8002', tld: 'localhost', domain: '' }, origin: 'http://localhost:8002', strategy: 'http', visiting: false, domainName: 'localhost', fileServer: null } +0ms
  cypress:server:timers queuing timer id 472 after 30000 ms +1ms
  cypress:server:timers child received timer id 472 +694ms
  cypress:server:openproject launching browser: electron, spec: cypress/integration/stages/dispatching-stage.espec.js +1ms
  cypress:server:browsers opening browser electron +0ms
  cypress:server:browsers:electron open { browserName: 'electron', url: 'http://localhost:8002/__/#/tests/integration/stages/dispatching-stage.espec.js' } +0ms
  cypress:server:saved_state noop saved state +0ms
  cypress:server:browsers:electron got saved state +0ms
  cypress:server:timers queuing timer id 473 after 30000 ms +184ms
  cypress:server:timers child received timer id 473 +186ms
  cypress:server:browsers:electron received saved state {} +2ms
  cypress:server:browsers:electron browser window options { width: 1280, height: 720, show: true, automationMiddleware: { onAfterResponse: [Function] }, projectRoot: '/home/travis/build/sennder/octopus', browsers: [ { name: 'chrome', displayName: 'Chrome', version: '62.0.3202.94', path: 'google-chrome', majorVersion: '62' }, { name: 'electron', displayName: 'Electron', version: '59.0.3071.115', path: '', majorVersion: '59', info: 'Electron is the default browser that comes with Cypress. This is the browser that runs in headless mode. Selecting this browser is useful when debugging. The version number indicates the underlying Chromium version that Electron uses.' } ], proxyUrl: 'http://localhost:38231', userAgent: null, proxyServer: 'http://localhost:38231', socketIoRoute: '/__socket.io', chromeWebSecurity: true, url: 'http://localhost:8002/__/#/tests/integration/stages/dispatching-stage.espec.js', isTextTerminal: true, browser: { name: 'electron', displayName: 'Electron', version: '59.0.3071.115', path: '', majorVersion: '59', info: 'Electron is the default browser that comes with Cypress. This is the browser that runs in headless mode. Selecting this browser is useful when debugging. The version number indicates the underlying Chromium version that Electron uses.', isHeadless: false, isHeaded: true }, x: null, y: null, devTools: false, minWidth: 100, minHeight: 100, contextMenu: true, trackState: { width: 'browserWidth', height: 'browserHeight', x: 'browserX', y: 'browserY', devTools: 'isBrowserDevToolsOpen' }, frame: true, recordFrameRate: null, onPaint: null, webPreferences: { chromeWebSecurity: true, nodeIntegration: false, backgroundThrottling: false } } +7ms
  cypress:server:plugins plugin event registered? { event: 'before:browser:launch', isRegistered: false } +1ms
  cypress:server:browsers:electron launching browser window to url: http://localhost:8002/__/#/tests/integration/stages/dispatching-stage.espec.js +1ms
  cypress:server:timers child sending timer id 413 +59ms
  cypress:server:timers child sending timer id 414 +17ms
  ...
  cypress:server:timers child sending timer id 471 +11ms
No output has been received in the last 10m0s, this potentially indicates a stalled build or something wrong with the build itself.
Check the details on how to adjust your build configuration on: https://docs.travis-ci.com/user/common-build-problems/#Build-times-out-because-no-output-was-received
The build has been terminated
@brandonb927

This comment has been minimized.

brandonb927 commented Aug 13, 2018

It appears 3.1.0 was released today, going to test it out to see if this squashes the bug here once and for all!

@kamituel

This comment has been minimized.

kamituel commented Aug 15, 2018

@brandonb927 Definitely do. It fixed this issue for us. Yay!

@brandonb927

This comment has been minimized.

brandonb927 commented Aug 15, 2018

I have a high degree of confidence that we can finally upgrade to 3.1.0 from 2.1.0, upgrading today.

@rnb-web-dev

This comment has been minimized.

rnb-web-dev commented Oct 16, 2018

I'm still seeing the bug on 3.1.0

@brandonb927

This comment has been minimized.

brandonb927 commented Oct 16, 2018

I completely forgot to come back to this and make a note that the 3.1.0 release definitely fixed this finally and we've been running it on our Jenkins nodes for some time now with no issues (well, none related to this issue at least).

@kamituel

This comment has been minimized.

kamituel commented Oct 18, 2018

Running 3.1.0 on our CI for ~2 months, I've haven't seen this issue reappear even once (whereas on 3.0 it'd be happening every day). So @rnb-web-dev, I'd suggest double checking if your issue is actually the same.

@davidzambrana

This comment has been minimized.

davidzambrana commented Oct 18, 2018

Same here, haven't seen this one popping up in the last weeks 👍

@krzkaczor

This comment has been minimized.

krzkaczor commented Oct 20, 2018

I am getting in on 3.1 but I am pretty sure that I found what causes it! I our case, its triggered when link to PDF file accidentally clicked and there is system dialog about saving file popping out.

Its not reproducble in "dev" mode only "run". @brian-mann i hope it helps you to write repro.

EDIT:
Okay i found the root cause. Turns out the exact place clicked by ".click" differs between electron and chrome runner so we had a button with a link inside (to pdf) and on CI link was clicked instead of button. You may see it here: https://github.com/OasisDEX/oasis-direct/pull/129/files

@brandonb927

This comment has been minimized.

brandonb927 commented Oct 22, 2018

@krzkaczor that sounds like normal behaviour for Cypress and isn’t related to this original issue.

2 similar comments
@brandonb927

This comment was marked as resolved.

brandonb927 commented Oct 22, 2018

@krzkaczor that sounds like normal behaviour for Cypress and isn’t related to this original issue.

@brandonb927

This comment was marked as resolved.

brandonb927 commented Oct 22, 2018

@krzkaczor that sounds like normal behaviour for Cypress and isn’t related to this original issue.

@cypress-io cypress-io locked as resolved and limited conversation to collaborators Nov 10, 2018

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.