Process exits with 1 minute delay #5

tsalzinger · 2014-05-28T09:12:33Z

I currently use gulp-karma for executing my tests from within gulp but as I'm no fan of all the gulp wrappers around existing functionality I wanted to switch to the proposed method described here. The setup and configuration was pretty straight forward but somehow karma prevents the whole process from shutting down (It does so eventually - with 1 minute delay to be specific).

My issue can be seen by the following output (i added a small wrapper which prints timestamps before and after executing gulp):

Starting @ 10:36:03,69
[gulp] Using gulpfile C:\private\src\gulp-karma\gulpfile.js
[gulp] Starting 'test'...
INFO [karma]: Karma v0.12.16 server started at http://localhost:9876/
INFO [launcher]: Starting browser Chrome
INFO [Chrome 35.0.1916 (Windows)]: Connected on socket tRl4URuNtzR0dDTX-NG8 with
Chrome 35.0.1916 (Windows): Executed 1 of 1 SUCCESS (0.01 secs / 0.001 secs)
[gulp] Finished 'test' after 2.38 s
Finished @ 10:37:06,52

After some research I discovered that this isn't a 'new' issue, but should be fixed in the latest release (0.12.16).
The issues i found:
#3
karma-runner/karma#1035
karma-runner/karma#1054

The text was updated successfully, but these errors were encountered:

pkozlowski-opensource · 2014-05-28T09:17:54Z

@tscheinecker I would be very much interested in tracking down all the timeouts that we might have missed.... but to do so I will need a minimal project that reproduces the issue plus more info about node version used.

Could you put together a repository with a minimal reproduce scenario? Are you facing the same issue with the sample project from this repo?

tsalzinger · 2014-05-28T14:24:54Z

@pkozlowski-opensource i use node 0.10.26 and yes i can reproduce it with the sample project from this repo - the output i posted above is from that exact test
i also was able to reproduce it here https://github.com/lazd/gulp-karma-test/tree/purekarma

pkozlowski-opensource · 2014-05-28T16:56:07Z

@tscheinecker hmm, this sounds like something possibly windows / particular node version specific. Here is the output I'm getting with node 0.10.21 on Mac:

 time gulp test
[gulp] Using file /Users/pawelkozlowski/work/gitrepos/pkozlowski-opensource/gulp-karma/gulpfile.js
[gulp] Working directory changed to /Users/pawelkozlowski/work/gitrepos/pkozlowski-opensource/gulp-karma
[gulp] Running 'test'...
INFO [karma]: Karma v0.12.16 server started at http://localhost:9876/
INFO [launcher]: Starting browser Chrome
INFO [Chrome 35.0.1916 (Mac OS X 10.9.2)]: Connected on socket f1Eay7CO2UWhtQPKvVht with id 91366075
Chrome 35.0.1916 (Mac OS X 10.9.2): Executed 1 of 1 SUCCESS (0.02 secs / 0.002 secs)
[gulp] Finished 'test' in 2.47 s

real    0m2.937s
user    0m2.972s
sys 0m0.758s

and indeed Karma exists immediately. I've tested the same correct behaviour on Linux (ubuntu).

I can dust off my old win machine and try to test if this is indeed Windows specific, but you could also help debugging this but putting somewhere here (in your local node_modules karma folder):
https://github.com/karma-runner/karma/blob/master/lib/server.js#L215
this code:

console.log(process._getActiveHandles());

that should list all the timers that might block Karma's exit.

tsalzinger · 2014-05-29T21:12:18Z

@pkozlowski-opensource thanks for the info
here's the output i got when i put the statement at line 216:

Starting @ 23:16:00,01
[gulp] Using gulpfile C:\private\src\gulp-karma\gulpfile.js
[gulp] Starting 'test'...
INFO [karma]: Karma v0.12.16 server started at http://localhost:9876/
INFO [launcher]: Starting browser Chrome
INFO [Chrome 35.0.1916 (Windows)]: Connected on socket sZhK8Hm4aQRf8chf1vH1 with
Chrome 35.0.1916 (Windows): Executed 1 of 1 SUCCESS (0.01 secs / 0.001 secs)
[ { domain: null,
    _events:
     { connection: [Function: createServer],
       error: [Function: serverError],
       timeout: [Function: serverTimeout],
       close: [Object] },
    _maxListeners: 10,
    _connections: 0,
    connections: [Getter/Setter],
    _handle:
     { fd: null,
       writeQueueSize: 0,
       onconnection: [Function: onconnection],
       owner: [Circular] },
    _usingSlaves: false,
    _slaves: [],
    allowHalfOpen: false,
    _connectionKey: '4:0.0.0.0:10843',
    online: true },
  { domain: null,
    _events:
     { connection: [Object],
       clientError: [Function],
       upgrade: [Object],
       error: [Object],
       request: [Function],
       close: [Function] },
    _maxListeners: 10,
    _connections: 0,
    connections: [Getter/Setter],
    _handle:
     { fd: null,
       writeQueueSize: 0,
       onconnection: [Function: onconnection],
       owner: [Circular] },
    _usingSlaves: false,
    _slaves: [],
    allowHalfOpen: true,
    httpAllowHalfOpen: false,
    timeout: 120000,
    '@': [Function: connection],
    _connectionKey: '4:0.0.0.0:9876' },
  { _idleNext:
     { _idleTimeout: 10000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398161915,
       _onTimeout: [Function: wrapper],
       _repeat: true },
    _idlePrev:
     { _idleTimeout: 10000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398161915,
       _onTimeout: [Function: wrapper],
       _repeat: true },
    msecs: 10000,
    ontimeout: [Function: listOnTimeout] },
  { _idleNext:
     { _idleTimeout: 60000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398164346,
       _onTimeout: [Function],
       _repeat: false },
    _idlePrev:
     { _idleTimeout: 60000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398164346,
       _onTimeout: [Function],
       _repeat: false },
    msecs: 60000,
    ontimeout: [Function: listOnTimeout] },
  { _idleNext:
     { _idleTimeout: 25000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398164221,
       _onTimeout: [Function],
       _repeat: false },
    _idlePrev:
     { _idleTimeout: 25000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398164221,
       _onTimeout: [Function],
       _repeat: false },
    msecs: 25000,
    ontimeout: [Function: listOnTimeout] } ]
[gulp] Finished 'test' after 2.52 s
Finished @ 23:17:04,38

and here's the output when I put it at line 230:

Starting @ 23:18:38,35
[gulp] Using gulpfile C:\private\src\gulp-karma\gulpfile.js
[gulp] Starting 'test'...
INFO [karma]: Karma v0.12.16 server started at http://localhost:9876/
INFO [launcher]: Starting browser Chrome
INFO [Chrome 35.0.1916 (Windows)]: Connected on socket TpznQxFchrgeI5It2VdS with
Chrome 35.0.1916 (Windows): Executed 1 of 1 SUCCESS (0.01 secs / 0.001 secs)
[ { domain: null,
    _events: {},
    _maxListeners: 10,
    _connections: 0,
    connections: [Getter/Setter],
    _handle: null,
    _usingSlaves: false,
    _slaves: [],
    allowHalfOpen: false,
    _connectionKey: '4:0.0.0.0:10843',
    online: true },
  { domain: null,
    _events:
     { connection: [Object],
       clientError: [Function],
       upgrade: [Object],
       error: [Object],
       request: [Function],
       close: [Object] },
    _maxListeners: 10,
    _connections: 0,
    connections: [Getter/Setter],
    _handle: null,
    _usingSlaves: false,
    _slaves: [],
    allowHalfOpen: true,
    httpAllowHalfOpen: false,
    timeout: 120000,
    '@': [Function: connection],
    _connectionKey: '4:0.0.0.0:9876' },
  { _idleNext:
     { _idleTimeout: 10000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398318936,
       _onTimeout: [Function: wrapper],
       _repeat: true },
    _idlePrev:
     { _idleTimeout: 10000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398318936,
       _onTimeout: [Function: wrapper],
       _repeat: true },
    msecs: 10000,
    ontimeout: [Function: listOnTimeout] },
  { _idleNext:
     { _idleTimeout: 60000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398321461,
       _onTimeout: [Function],
       _repeat: false },
    _idlePrev:
     { _idleTimeout: 60000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398321461,
       _onTimeout: [Function],
       _repeat: false },
    msecs: 60000,
    ontimeout: [Function: listOnTimeout] },
  { _idleNext:
     { _idleTimeout: 25000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398321334,
       _onTimeout: [Function],
       _repeat: false },
    _idlePrev:
     { _idleTimeout: 25000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398321334,
       _onTimeout: [Function],
       _repeat: false },
    msecs: 25000,
    ontimeout: [Function: listOnTimeout] },
  { _idleNext:
     { _idleTimeout: 3000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398321486,
       _onTimeout: [Function],
       _repeat: false },
    _idlePrev:
     { _idleTimeout: 3000,
       _idlePrev: [Circular],
       _idleNext: [Circular],
       _idleStart: 1401398321486,
       _onTimeout: [Function],
       _repeat: false },
    msecs: 3000,
    ontimeout: [Function: listOnTimeout] } ]
[gulp] Finished 'test' after 2.58 s
Finished @ 23:19:41,49

philjones88 · 2014-06-04T16:50:22Z

I'm seeing something similar. I upgraded to node on Windows to check but still happens on latest.

Mac (0.10.25): Runs and exits perfectly.
Win 8.1 (0.10.25 and 0.10.28): Runs and waits 1 minute (I'm assuming, took a while, didn't put timers in)

Gulp: 3.6.2
Karma: 0.12.16

pkozlowski-opensource · 2014-06-04T17:34:21Z

@philjones88 thnx for the info. So, for now it looks like something specific to Windows...

pkozlowski-opensource · 2014-06-04T17:53:34Z

@tscheinecker @philjones88 this sounds odd... The only timeout of ~1 minute seems to be coming from the _onTimeout method that existed only in the very old version of Karma.... Anyway, need to dig into this on my Win machine.

pkozlowski-opensource · 2014-06-05T10:01:33Z

OK, managed to reproduce this on Windows. The timeout that prevents node process from existing is coming from socket.io (yeh, another one...):
https://github.com/Automattic/socket.io/blob/0.9/lib/transport.js#L216

For now I'm not sure why it happens on Win only and how to clear this timeout so if there are people more familiar with the socket.io code - any help would be appreciated.

tsalzinger · 2014-06-06T13:56:24Z

@pkozlowski-opensource thanks for investigating this issue
hope this can be fixed in due time, but for now I can probably live with the 1 minute delay - I think it is still preferable to using gulp-karma plugin :)

maku · 2014-06-25T09:48:34Z

I have the same problems on windows (delay of ~1 min before exit).
Any progress made on this topic??

pkozlowski-opensource · 2014-06-25T10:23:05Z

@maku in fact yes. Just yesterday a colleague of mine found a work-arround that could be applied on Karma, see karma-runner/karma#1109 for more details. Let's wait for input from other Karma contributors and eventually work-around this in Karma. The other option is to fix the issue in the socket.io itself, but I'm not sure how likely they are to accept a patch to the 0.9.x line.

maku · 2014-06-25T15:08:07Z

@pkozlowski-opensource : thanks for answering. I added "sockets[key].disconnect();" locally in server.js and now it works as expected. I hope that a final solution is not far away.

nonplus · 2014-06-26T21:56:19Z

@pkozlowski-opensource : Thanks for the link. Instead of directly modifying the karma source, I monkey-patch it at the top of my gulpfile.js:

// Workaround for karma's timeout issues on Windows
// See: https://github.com/karma-runner/gulp-karma/issues/5
var io = require('karma/node_modules/socket.io');
// Monkey patch io.listen
var io_listen = io.listen;
io.listen = function() {
    var server = io_listen.apply(io, [].slice.call(arguments));
    server.on('connection', function(socket) {
        // Monkey patch socket.removeAllListeners
        var socket_removerAllListeners = socket.removeAllListeners;
        socket.removeAllListeners = function(evt) {
            socket_removerAllListeners.apply(socket,[].slice.call(arguments));
            if(evt === 'disconnect') {
                // Fix the timeout problem
                socket.disconnect();
            }
        };
    });
    return server;
};

pkozlowski-opensource · 2014-07-11T16:14:24Z

Good news - the latest version of Karma (0.12.17) contains a fix that solves this issue! Yay!

nweldev · 2016-01-11T17:21:51Z

I still get this bug ... exit after 1 minute.

Yet, I'm on node 5.4.0 with gulp 3.9.0 and karma 0.13.19.

nonplus · 2016-01-12T16:35:44Z

+1

I work around the problem by explicitly specifying karma 0.13.18 and socket.io 1.3.7 in my package.json file.

dignifiedquire · 2016-01-12T16:36:16Z

This is being tracked in karma-runner/karma#1788

dignifiedquire · 2016-01-12T16:37:25Z

@pkozlowski-opensource if you got a moment to look into this, as you were able to track this down the last time I'd appreciate it.

shuyudev · 2017-03-22T23:29:33Z

Still get this. There is huge delay for exit.
Karma 1.4.0
Gulp 4.0.0
Node 6.5.0

johannesjo · 2017-11-30T21:11:06Z

Still an issue..

tsalzinger closed this as completed May 29, 2014

tsalzinger reopened this May 29, 2014

pkozlowski-opensource mentioned this issue Jun 25, 2014

setTimout in socket.io prevents Karma from exiting on Windows karma-runner/karma#1109

Closed

This was referenced Jul 1, 2014

fix(server): Force socket.io clients disconnection on Windows karma-runner/karma#1121

Merged

Public API does not provide hooks for server started, all browsers captured, etc karma-runner/karma#1037

Closed

pkozlowski-opensource closed this as completed in 6839416 Jul 11, 2014

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Process exits with 1 minute delay #5

Process exits with 1 minute delay #5

tsalzinger commented May 28, 2014

pkozlowski-opensource commented May 28, 2014

tsalzinger commented May 28, 2014

pkozlowski-opensource commented May 28, 2014

tsalzinger commented May 29, 2014

philjones88 commented Jun 4, 2014

pkozlowski-opensource commented Jun 4, 2014

pkozlowski-opensource commented Jun 4, 2014

pkozlowski-opensource commented Jun 5, 2014

tsalzinger commented Jun 6, 2014

maku commented Jun 25, 2014

pkozlowski-opensource commented Jun 25, 2014

maku commented Jun 25, 2014

nonplus commented Jun 26, 2014

pkozlowski-opensource commented Jul 11, 2014

nweldev commented Jan 11, 2016

nonplus commented Jan 12, 2016

dignifiedquire commented Jan 12, 2016

dignifiedquire commented Jan 12, 2016

shuyudev commented Mar 22, 2017

johannesjo commented Nov 30, 2017

Process exits with 1 minute delay #5

Process exits with 1 minute delay #5

Comments

tsalzinger commented May 28, 2014

pkozlowski-opensource commented May 28, 2014

tsalzinger commented May 28, 2014

pkozlowski-opensource commented May 28, 2014

tsalzinger commented May 29, 2014

philjones88 commented Jun 4, 2014

pkozlowski-opensource commented Jun 4, 2014

pkozlowski-opensource commented Jun 4, 2014

pkozlowski-opensource commented Jun 5, 2014

tsalzinger commented Jun 6, 2014

maku commented Jun 25, 2014

pkozlowski-opensource commented Jun 25, 2014

maku commented Jun 25, 2014

nonplus commented Jun 26, 2014

pkozlowski-opensource commented Jul 11, 2014

nweldev commented Jan 11, 2016

nonplus commented Jan 12, 2016

dignifiedquire commented Jan 12, 2016

dignifiedquire commented Jan 12, 2016

shuyudev commented Mar 22, 2017

johannesjo commented Nov 30, 2017