Skip to content
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

v6 coverage runs can fail dues to maxHttpBufferSize change in socket.io v3 #3621

Closed
ddolcimascolo opened this issue Jan 15, 2021 · 14 comments · Fixed by #3626 or karronoli/redpen#10
Closed
Labels

Comments

@ddolcimascolo
Copy link

Hi guys,

Our build starts to fail when we upgrade karma to v6.0.0. All tests run without problem, but Karma thinks the browser disconnects right after executing the tests (or the browser actually disconnects, but that doesn't make Karma yell in v5.2).

I tracked it down and reproduced with a single test running in .only (we're using Mocha as a framework) so I suppose it's not a problem with the actual tests, but maybe related to the actual amount of JS code we're oading in the browser. Again, in v5.2 they run fine.

I'm attaching karma.v5.log and karma.v6.log in DEBUG level that show the exact same run, one with 5.2.3 and the other with 6.0.0. The only step in-between these two runs is the upgrade of Karma.

A few additional information on our setup (and you have the full config object at the beginning of the log file)

I'm kinda stuck now, not knowing where to go to track the problem even further. I will provide any additional information you may require but would appreciate help from Karma's community. In addition, I volounteer to make a PR if we eventually find a problem in Karma itself !

Thanks,
Regards,

David

@johnjbarton
Copy link
Contributor

johnjbarton commented Jan 15, 2021 via email

@ddolcimascolo
Copy link
Author

Thx, I'm not sure which timeout you're referring to. Tests do run at "normal" speed and complete just fine. But a few milliseconds later instead of the typical tests-done-browser-closing scenario I'm seeing an error about browser disconnecting, then reconnecting and then nothing until "no message in 30s" error, which I assume is expected because tests are done so there nothing left for the browser to do...

@johnjbarton
Copy link
Contributor

johnjbarton commented Jan 16, 2021 via email

@ddolcimascolo
Copy link
Author

Thx, I'll try and report here

@robertknight
Copy link

robertknight commented Jan 19, 2021

We experienced a similar issue after upgrading from v5.2.3 to 6.0.0. I attempted changing the pingTimeout setting from the default to 60000 without success. I am using Chrome Headless 88.0.4298.0 on macOS 11.

I discovered that whether the issue occurred depended on the amount of code in the test bundle. I tried various combinations of files and eventually discovered that it would reliably succeed with a specific number of files fully included and one file included with certain statements commented out. If I uncommented one more statement, it would fail.

After adding some low-level logging to Socket.IO, I found that when the amount of code was just small enough to allow the tests to pass, the raw complete message sent over the WebSocket via Socket.IO was 999815 chars long. Further experimentation found that it seemed to fail as soon as this value exceeded 1000000. Adding some extra logging in engine.io I uncovered this error that was being swallowed:

RangeError: Max payload size exceeded

This is coming from engine.io/node_modules/ws/lib/receiver.js.

In our project we are using Istanbul for code coverage. The "complete" message sent at the end of the test run includes all of the code coverage data. It seems that if there is enough code, this data can push the size of the "complete" message past this threshold.

I see from the changelog that one of the changes in Karma v6 is an upgrade to Socket.io v3, so I guess this is probably related.

Edit: I see the original reporter was also using Istanbul as well, so they probably had the same issue.

@robertknight
Copy link

The maximum payload size is coming from here in engine.io: https://github.com/socketio/engine.io/blob/e5b307c16d8e7594fcec4eb23508f23f78546dc6/lib/server.js#L29.

Changing the maxHttpBufferSize value locally to a larger value solves the issue for me. Obviously this configuration needs to be overridden in the proper way.

The fact that Istanbul sends all of its code coverage data over the WebSocket in one request at the end of the test run is probably not ideal, but that's going to be harder to fix.

@cyco
Copy link

cyco commented Jan 19, 2021

I just ran into the same issue. After executing tests in my project the debug output shows a message similar to the one mentioned in #3359 (comment):

19 01 2021 18:48:15.419:DEBUG [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: onSocketDisconnect transport error
19 01 2021 18:48:15.420:DEBUG [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: Disconnected during run, waiting 2000ms for reconnecting.
19 01 2021 18:48:15.420:DEBUG [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: EXECUTING -> EXECUTING_DISCONNECTED
19 01 2021 18:48:16.109:DEBUG [karma-server]: A browser has connected on socket DnnHrBJRoX4zK5QKAAAD
19 01 2021 18:48:16.111:DEBUG [web-server]: upgrade /socket.io/?EIO=4&transport=websocket&sid=0z18ahVqAAJkbW85AAAC
19 01 2021 18:48:16.119:DEBUG [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: Lost socket connection, but browser continued to execute. Reconnected on socket DnnHrBJRoX4zK5QKAAAD.
19 01 2021 18:48:16.119:DEBUG [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: EXECUTING_DISCONNECTED -> EXECUTING
19 01 2021 18:48:46.122:WARN [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: Disconnected (0 times) , because no message in 30000 ms.

Chrome Headless 87.0.4280.141 (Mac OS 11.0.0) ERROR
  Disconnected , because no message in 30000 ms.
19 01 2021 18:48:46.126:DEBUG [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: EXECUTING -> DISCONNECTED
Chrome Headless 87.0.4280.141 (Mac OS 11.0.0): Executed 2877 of 3012 (skipped 135) DISCONNECTED (1 min 33.564 secs / 37.044 secs)
19 01 2021 18:48:46.133:DEBUG [launcher]: CAPTURED -> BEING_KILLED
19 01 2021 18:48:46.134:DEBUG [launcher]: BEING_KILLED -> BEING_FORCE_KILLED
19 01 2021 18:48:46.134:DEBUG [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: DISCONNECTED -> DISCONNECTED
19 01 2021 18:48:46.137:DEBUG [reporter.coverage-istanbul]: Writing coverage reports: [ 'lcovonly', 'html' ]
19 01 2021 18:48:46.174:DEBUG [karma-server]: Run complete, exiting.
19 01 2021 18:48:46.174:DEBUG [launcher]: Disconnecting all browsers
19 01 2021 18:48:46.175:DEBUG [launcher]: BEING_FORCE_KILLED -> BEING_FORCE_KILLED
19 01 2021 18:48:46.175:DEBUG [proxy]: Destroying proxy agents
19 01 2021 18:48:46.176:DEBUG [launcher]: Process ChromeHeadless exited with code null and signal SIGTERM
19 01 2021 18:48:46.177:DEBUG [temp-dir]: Cleaning temp dir /var/folders/0w/5jtpbk992090s9lq47g_k6300000gn/T/karma-38508564
19 01 2021 18:48:46.181:DEBUG [Chrome Headless 87.0.4280.141 (Mac OS 11.0.0)]: onSocketDisconnect transport close
19 01 2021 18:48:46.197:DEBUG [launcher]: Finished all browsers
19 01 2021 18:48:46.197:DEBUG [launcher]: BEING_FORCE_KILLED -> FINISHED
19 01 2021 18:48:46.197:DEBUG [launcher]: FINISHED -> FINISHED

And the last sent message is rather large (due to coverage data):

Screenshot 2021-01-19 at 18 52 19

Increasing the default buffer size for the socket.io server also fixes the problem for me.

@ddolcimascolo
Copy link
Author

Good catch @robertknight and thx for investigating this. As you've noted, we're indeed using Istanbul for our code coverage report and probably fall into the same hole...

So the idea is to make socket.io's maxHttpBufferSize configurable through Karma config right? If so, this is something I can handle in a PR. Will look into it ASAP

@ddolcimascolo
Copy link
Author

@johnjbarton Meanwhile, do you mind pinning this issue so that it's easier to find for users suffering the regression?

@cyco
Copy link

cyco commented Jan 19, 2021

I think reading maxHttpBufferSize from the Karma config (similar to transports) should work. Is there a way to catch the Max payload size exceeded error that @robertknight mentioned and log it? That way people would know when to increase the buffer size.

@ddolcimascolo
Copy link
Author

@cyco I think you're right, actually. Identifying and logging the issue is probably the best option. Otherwise people will never know they need to increase that buffer size...

Detecting, logging and suggesting to increase the timeout would be a good way to fix the issue I suppose

@johnjbarton johnjbarton pinned this issue Jan 19, 2021
@johnjbarton
Copy link
Contributor

@robertknight

Adding some extra logging in engine.io I uncovered this error that was being swallowed:

Is there anything that karma can do to surface this error message to the user?

@johnjbarton
Copy link
Contributor

I think we can set the maxHttpBufferSize to 1e8 to avoid most cases.

From https://socket.io/docs/v3/migrating-from-2-x-to-3-0/index.html

Saner default values
  * the default value of maxHttpBufferSize was decreased from 100MB to 1MB.

@johnjbarton johnjbarton changed the title Potential problem with v6, help appreciated v6 coverage runs can fail dues to maxHttpBufferSize change in socket.io v3 Jan 20, 2021
johnjbarton added a commit to johnjbarton/karma that referenced this issue Jan 20, 2021
karmarunnerbot pushed a commit that referenced this issue Jan 20, 2021
## [6.0.1](v6.0.0...v6.0.1) (2021-01-20)

### Bug Fixes

* **server:** set maxHttpBufferSize to the socket.io v2 default ([#3626](#3626)) ([69baddc](69baddc)), closes [#3621](#3621)
* restore `customFileHandlers` provider ([#3624](#3624)) ([25d9abb](25d9abb))
@karmarunnerbot
Copy link
Member

🎉 This issue has been resolved in version 6.0.1 🎉

The release is available on:

Your semantic-release bot 📦🚀

@devoto13 devoto13 unpinned this issue Feb 2, 2021
anthony-redFox pushed a commit to anthony-redFox/karma that referenced this issue May 16, 2023
## [6.0.1](karma-runner/karma@v6.0.0...v6.0.1) (2021-01-20)

### Bug Fixes

* **server:** set maxHttpBufferSize to the socket.io v2 default ([karma-runner#3626](karma-runner#3626)) ([69baddc](karma-runner@69baddc)), closes [karma-runner#3621](karma-runner#3621)
* restore `customFileHandlers` provider ([karma-runner#3624](karma-runner#3624)) ([25d9abb](karma-runner@25d9abb))
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
5 participants