Karma: v6 coverage runs can fail dues to maxHttpBufferSize change in socket.io v3

[ddolcimascolo]

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)

• The actual application is using AngularJS
• We use Mocha as our test framework
• We run tests in Chrome headless only, using karma-chrome-launcher
• We use karma-coverage-istanbul-instrumenter and karma-coverage-istanbul-reporter to generate coverage report information
• We preprocess HTML templates to make them AngularJS modules (yeah... more JS code loaded :p)

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]

This looks similar to an issue we have been working on (but it happens in
karma v5). A colleague analyzed it and believes that the problem is
related to lost socket io packets during the second (reconnecting) upgrade.
The first upgrade happens early and has no contention from the page load.
But the problem cases are attempting to reconnect during the page load
processing when the browser is running flat out to compile and load
incoming js files. The contention delays the upgrade and during that time
socket events get queued or lost. Try setting longer timeouts until we
sort this out one out.

On Fri, Jan 15, 2021 at 9:24 AM David DOLCIMASCOLO [e-mail]
wrote:

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
https://github.com/karma-runner/karma/files/5821996/karma.v5.log and
karma.v6.log
https://github.com/karma-runner/karma/files/5821998/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)

• The actual application is using AngularJS
• We use Mocha as our test framework
• We run tests in Chrome headless only, using karma-chrome-launcher
  https://www.npmjs.com/package/karma-chrome-launcher
• We use karma-coverage-istanbul-instrumenter
  https://www.npmjs.com/package/karma-coverage-istanbul-instrumenter
  and karma-coverage-istanbul-reporter
  https://www.npmjs.com/package/karma-coverage-istanbul-reporter to
  generate coverage report information
• We preprocess HTML templates to make them AngularJS modules (yeah...
  more JS code loaded :p)

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

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/karma-runner/karma/issues/3621, or unsubscribe
https://github.com/notifications/unsubscribe-auth/AABSGAW62I5EBYCBBKCZKI3S2B25NANCNFSM4WELTU3Q
.

[ddolcimascolo]

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]

My interpretation of your scenario is that the test "complete just fine"
but then fail to report results to the server. The results get lost during
the reconnect and thus the server eventually assumes the browser crashed
and says "no message". Try setting a larger pingTimeout
http://karma-runner.github.io/6.0/config/configuration-file.html

On Sat, Jan 16, 2021 at 7:49 AM David DOLCIMASCOLO [e-mail]
wrote:

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...

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/karma-runner/karma/issues/3621#issuecomment-761585359,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AABSGATROJT25HCQ3VUMCTLS2GYSFANCNFSM4WELTU3Q
.

[ddolcimascolo]

Thx, I'll try and report here

[robertknight]

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]

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]

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 https://github.com/karma-runner/karma/issues/3359#issuecomment-631556049:

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

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

[ddolcimascolo]

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]

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

[cyco]

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]

@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]

@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]

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.

[karmarunnerbot]

:tada: This issue has been resolved in version 6.0.1 :tada:

The release is available on:

• npm package (@latest dist-tag)
• GitHub release

Your semantic-release bot :package::rocket: