search

karma-runner / gulp-karma

Example of using Karma with Gulp.
310 stars 41 forks source link

Process exits with 1 minute delay #5

Closed tsalzinger closed 10 years ago

tsalzinger commented 10 years ago

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: https://github.com/karma-runner/gulp-karma/issues/3 https://github.com/karma-runner/karma/issues/1035 https://github.com/karma-runner/karma/issues/1054

pkozlowski-opensource commented 10 years ago

@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 commented 10 years ago

@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 commented 10 years ago

@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 commented 10 years ago

@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 commented 10 years ago

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 commented 10 years ago

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

pkozlowski-opensource commented 10 years ago

@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 commented 10 years ago

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 commented 10 years ago

@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 commented 10 years ago

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

pkozlowski-opensource commented 10 years ago

@maku in fact yes. Just yesterday a colleague of mine found a work-arround that could be applied on Karma, see https://github.com/karma-runner/karma/issues/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 commented 10 years ago

@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 commented 10 years ago

@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 commented 10 years ago

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

nweldev commented 8 years ago

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 commented 8 years ago

+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 commented 8 years ago

This is being tracked in https://github.com/karma-runner/karma/issues/1788

dignifiedquire commented 8 years ago

@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 commented 7 years ago

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

johannesjo commented 6 years ago

Still an issue..