"test exited without ending"

[gritzko]

Hi!

Probabilistically, I get the following:

not ok 95 test exited without ending
  ---
    operator: fail
  ...
not ok 96 test exited without ending
  ---
    operator: fail
  ...

(more of the same)

    operator: fail
  ...
not ok 112 test exited without ending
  ---
    operator: fail
  ...
not ok 113 test exited without ending
  ---
    operator: fail
  ...

1..113
# tests 113
# pass  94
# fail  19

19 out of 20 runs are OK.
I am mostly annoyed by the fact I can not localize/attribute the error.

[joshrivers]

@gritzko Is this on Node, or in the browser?

[Raynos]

This means your test did not call assert.end().

Probably a race condition in your own code.

[kgryte]

I am seeing a similar issue. I have tests split across multiple files. When I run the tests using Istanbul

$  istanbul cover tape -- ./test/*.js 

some runs all complete (no errors) and others return an operator: fail error due to test exited without ending. In my case, the failed test resides in the last test file.

The tests are all synchronous, so no async race conditions. And all tests explicitly call t.end().

[Marak]

Are you certain your tests are idempotent and that the state of some tests
aren't affecting the state of other tests?

What happens if you run the tests individually? Do they work every time? If
so, the issue could be state related.

On Tue, Dec 29, 2015 at 3:51 PM, Athan notifications@github.com wrote:

I am seeing a similar issue. I have tests split across multiple files.
When I run the tests using Istanbul

$ istanbul cover tape -- ./test/*.js

some runs all complete (no errors) and others return an operator: fail
error due to test exited without ending. In my case, the failed test
resides in the last test file.

The tests are all synchronous, so no async race conditions. And all tests
explicitly call t.end().

—
Reply to this email directly or view it on GitHub
#223 (comment).

[gritzko]

@joshrivers node, AFAIR
@kgryte yes, looks like my case, there was explicit t.end() and the case was synchronous
I switched to tap, so I can not provide any more feedback.

[kgryte]

@Marak If I run each test file individually, the tests always pass. No tests share state.

[Marak]

@kgryte -

Can you describe the nature of the tests? If they are all synchronous tests I'm assuming they are performing no file-system or network based i/o? Or are they using synchronous file-system methods?

What I'm trying to ascertain is if you are accessing any shared resources across the tests which could be causing conflicting state.

[kgryte]

The tests are of the variety:

test( 'awesome test', function ( t ) {
  t.ok( 5 === 5, 'numbers are equal' );
  t.end();
});

In the last file which occasionally fails, I added additional (synchronous) dummy test cases to see what happens. The result is that either all tests pass or all fail due to the test exited without ending error.

[Marak]

@kgryte - Maybe the issue is with istanbul? What happens if you try using the tape test runner?

[kgryte]

@Marak Here is a link to the tests. To run the tests with istanbul => make test-cov.

[Marak]

What happens if you change up this require statement:

https://github.com/kgryte/utils-copy-error/blob/master/test/test.ctors.js#L6

var CTORS;

Then inside the first test put:

CTORS = require( './../lib/ctors.js' );

[kgryte]

Same result. Did the same for the test.js file. Tests only seem to be indeterminate for the last file (here, test.js).

[kgryte]

@Marak If I run the tests without istanbul, the tests pass; although, I cannot guarantee this is forever true, as I am not sure if tape has a race condition which is only apparent for longer load times (e.g., due to instrumentation).

[Marak]

@kgryte -

The thing is, I have some faith that tape is working right.

If the issue only comes up using istanbul, it might be in there, or it could be the structure of your tests.

Simple question, are you certain you are using the latest stable versions of all projects involved?

[kgryte]

@Marak Yes, I have the latest versions of all projects. So I did the following

# Instrument files beforehand and output to temporary directory...
$ istanbul instrument ./lib --output ./tmp

# Run the tests on the instrumented files...
$ tape ./test/*.js

I ran into the same issue. When tape runs tests which use instrumented code, I encounter occasional failed tests.

[Marak]

@kgryte - Did you try opening an issue in instanbul?

[kgryte]

@Marak I am not convinced that the issue is istanbul, especially now that I have used tape to run tests which directly require instrumented code in place of the raw files. In which case, istanbul is a non-factor as it is removed from the equation. I see the same probabilistic results.

[kgryte]

@Marak So, I put a console.log here https://github.com/substack/tape/blob/master/bin/tape#L31 . Here is what I see...

test/test.copy.js
test/test.ctors.js
TAP version 13
# file exports a function
ok 1 export is a function
# if not provided an error instance, the function throws an error
ok 2 throws when provided a string
ok 3 throws when provided a number
ok 4 throws when provided a object
ok 5 throws when provided a number
ok 6 throws when provided a undefined
ok 7 throws when provided a boolean
ok 8 throws when provided a object
ok 9 throws when provided a object
ok 10 throws when provided a function
# generic <Error> object
ok 11 separate instances
ok 12 instance of Error
ok 13 equal messages
ok 14 equal names
ok 15 equal stack trace
# <TypeError>
ok 16 separate instances
ok 17 instance of TypeError
ok 18 equal messages
ok 19 equal names
ok 20 equal stack trace
# <RangeError>
ok 21 separate instances
ok 22 instance of RangeError
ok 23 equal messages
ok 24 equal names
ok 25 equal stack trace
# <SyntaxError>
ok 26 separate instances
ok 27 instance of SyntaxError
ok 28 equal messages
ok 29 equal names
ok 30 equal stack trace
# <ReferenceError>
ok 31 separate instances
ok 32 instance of ReferenceError
ok 33 equal messages
ok 34 equal names
ok 35 equal stack trace
# <EvalError>
ok 36 separate instances
ok 37 instance of EvalError
ok 38 equal messages
ok 39 equal names
ok 40 equal stack trace
# <URIError>
ok 41 separate instances
ok 42 instance of URIError
ok 43 equal messages
ok 44 equal names
ok 45 equal stack trace
# error constructors are exposed via an exported object
ok 46 export is an object
test/test.js

Notice that the last file appears after the tests have run.

[kgryte]

@Marak The race condition belongs to tape on this one. I inserted a setTimeout statement into one of the other test files and now all tests always pass.

My running hypothesis is as follows: without the setTimeout, the first two files are periodically loaded and completed in the same event loop before the third file is loaded. By the time tape is "ready" for the third file and has begun running the tests, tape prematurely ends pending tests and claims that they failed to exit without ending. By inserting the setTimeout into one of the earlier files, earlier tests are pushed off to later event loops, allowing the third file to process and complete.

[kgryte]

Similar issues have been reported before: #160

[kgryte]

Update: if I use t.plan() instead of using t.end(), the tests seem to pass. So it seems like tape is prematurely ending tests before t.end() can be called.

Correction: I just had a build fail due to tests prematurely ending even when using t.plan().

[kgryte]

@Marak I added a console.log statement in the process.on( 'exit', clbk) handler https://github.com/substack/tape/blob/master/index.js#L80 . As can be seen from the logs below, the first two files are run and complete before the third file loads. The exit handler is called, thus causing the exitHarness to call t._exit() before the remaining tests have completed, and thus leading to failed tests.

test/test.copy.js
test/test.ctors.js
TAP version 13
# file exports a function
ok 1 export is a function
# if not provided an error instance, the function throws an error
ok 2 throws when provided a string
ok 3 throws when provided a number
ok 4 throws when provided a object
ok 5 throws when provided a number
ok 6 throws when provided a undefined
ok 7 throws when provided a boolean
ok 8 throws when provided a object
ok 9 throws when provided a object
ok 10 throws when provided a function
# generic <Error> object
ok 11 separate instances
ok 12 instance of Error
ok 13 equal messages
ok 14 equal names
ok 15 equal stack trace
# <TypeError>
ok 16 separate instances
ok 17 instance of TypeError
ok 18 equal messages
ok 19 equal names
ok 20 equal stack trace
# <RangeError>
ok 21 separate instances
ok 22 instance of RangeError
ok 23 equal messages
ok 24 equal names
ok 25 equal stack trace
# <SyntaxError>
ok 26 separate instances
ok 27 instance of SyntaxError
ok 28 equal messages
ok 29 equal names
ok 30 equal stack trace
# <ReferenceError>
ok 31 separate instances
ok 32 instance of ReferenceError
ok 33 equal messages
ok 34 equal names
ok 35 equal stack trace
# <EvalError>
ok 36 separate instances
ok 37 instance of EvalError
ok 38 equal messages
ok 39 equal names
ok 40 equal stack trace
# <URIError>
ok 41 separate instances
ok 42 instance of URIError
ok 43 equal messages
ok 44 equal names
ok 45 equal stack trace
# error constructors are exposed via an exported object
ok 46 export is an object
test/test.js
EXIT false
not ok 47 test exited without ending
  ---
    operator: fail
  ...

1..47
# tests 47
# pass  46
# fail  1

[Raynos]

This does sound like a bug given the following conditions:

• use tape binary and the globs
• All tests are synchronous.

Looks the race condition is here: https://github.com/substack/tape/blob/master/bin/tape#L28-L34

We really should "resolve" all globs in parallel; and then loop over ALL the files once instead of doing multiple loops.

As a temporary workaround @kgryte can do tape "./test/*.js". By wrapping the expression in quotes bash wont expand them to all of the files.

[kgryte]

@Raynos workaround works. All files are resolved before tests are run. Thanks!

[Marak]

@kgryte -

Thank you for the detailed bug report.

Also thanks to @Raynos for figuring it out!

[Marak]

Issue can be related to calling process.exit instead of actually closing the process down safely.

If you have any process.exit in tests, remove it. If the test isn't shutting down, try leaked-handles module to find open handler ( which needs to be closed for process to exit )

require('leaked-handles').set({
    fullStack: true, // use full stack traces
    timeout: 5000, // run every 30 seconds instead of 5.
    debugSockets: true // pretty print tcp thrown exceptions.
});

[Marak]

@ljharb @substack @Raynos -

I'm consistently getting errors and reports of errors from other developers trying to use the tape CLI to run multiple tests at once. Seems to be a race condition / timing issue. Could be due to user errors in the test code, but that's unavoidable.

If we switch to the tap binary on the same glob of tests, everything just works. Let me know if you have any idea or solution outside of dropping tape CLI for tap.

[ljharb]

@Marak can you elaborate on "at once"? One of the primary benefits of tape over tap is that it's lightweight and can also run in a browser. If those aren't concerns, and encouraging bad code to be written properly isn't an option, I think switching libs might make sense.

[Marak]

@ljharb

I mean to say when running tests with globs like tape test/*.js. I tried the recommendation of running tape "test/*.js", but that didn't help either.

It's just odd to me that these two commands are yielding much different test results:

 tape test/*.js
 tap test/*.js

Noted about primary benefits of tap versus tape and might choose to use tap for our server-side testing.

[ljharb]

I believe in that case tap may run each file in its own process, whereas tape runs them all in the same one? Just guessing tho.

Personally I usually node test/index.js and explicitly require in all my test files, so I don't use the tape binary at all - and never run into this problem. It might be something fixable in that tape binary code, perhaps.

[Marak]

@ljharb -

Are you saying that you require all your test files in one index.js file like found here: https://github.com/ljharb/object-keys/blob/master/test/index.js ?

One of our developers wanted to do the same and I'm not sure that would scale well for a project with many suites. Going to switch to tap here and see if it helps. Process-per-test seems fairly important, and makes sense why tap is doing better than tape for these server tests.

[ljharb]

@Marak yes, precisely that. My general sense is that when that doesn't scale, the project is too large, and thus must be split into smaller projects in their own repos.

[simonhac]

i'm pretty sure i've been fighting this issue all day. here's a barebones test that'll show it up:

const test = require('tape').test;

function _test(identifier) {
	console.log(`starting test ${identifier}`);
	test(`_test ${identifier}`, assert => {
		assert.true(true);
	});
}

function _runAsyncTests() {
	setTimeout(_test, 1000, `A`);
	setTimeout(_test, 3000, `B`);
}

_runAsyncTests();

here's the output:

starting test A
TAP version 13
# _test A
ok 1 should be truthy
starting test B
not ok 2 test exited without ending
  ---
    operator: fail
  ...
not ok 3 test exited without ending
  ---
    operator: fail
  ...

1..3
# tests 3
# pass  1
# fail  2

npm ERR! Test failed.  See above for more details.

Process finished with exit code 1

i've traced it through into tape with the debugger. node is trying to exit before the last test has been scheduled.

[ljharb]

@simonhac I trust that you realize that if you added an assert.plan(1) at the beginning or assert.done() at the end, that it would all work perfectly?

[simonhac]

thanks @ljharb -- do you mean that i should change my code to the following?

const test = require('tape').test;

function _test(identifier) {
	test(`_test ${identifier}`, assert => {
		assert.plan(1)
		assert.true(true);
		assert.end();
	});
}

function _runAsyncTests() {
	setTimeout(_test, 1000, `A`);
	setTimeout(_test, 3000, `B`);
}

unfortunately, that still fails:

TAP version 13
# _test A
ok 1 should be truthy
not ok 2 test exited without ending
  ---
    operator: fail
  ...

1..2
# tests 2
# pass  1
# fail  1

but i've worked out why -- will post in next comment.

[simonhac]

ok, i think i've worked this out.

as soon as the list of executing tests is empty tape starts to shut down. any test 'scheduled' after the list becomes empty will generate a test exited without ending failure.

check out this simple example:

const test = require('tape').test;

function _test(name) {
	test(`test ${name}`, t => {
		t.plan(1);
		t.pass(name);
		t.end();
	});
}

_test(`huey`);
_test(`dewey`);

setTimeout(function () {
	_test(`louie`);
}, 100);

the runtime gets to the bottom of the script before the deferred task to schedule the 'louie' test is executed, and we get the following failing test report:

TAP version 13
# test huey
ok 1 huey
# test dewey
ok 2 dewey
not ok 3 test exited without ending
  ---
    operator: fail
  ...

1..3
# tests 3
# pass  2
# fail  1

if i add the following statement to the bottom it works just fine!

test(`afterTests`, t => {
	setTimeout(function () {
		t.end();
	}, 1000);
});

it is not immediately intuitive to the casual reader why this might make it work, but this supports my theory above. it would be nicer if tape didn't exit until the script and all deferred tasks had executed.

ps. you may ask why i have delayed tests -- i have a test harness that generates tests only once it has asynchronously read in a file. i can code around this (by loading the file in a dummy test at the top of the script), but i thought it was worth explaining what i found because it looks like this issue frequently bites others.

[ljharb]

Because you want var test = require('tape'), and to invoke that.

[simonhac]

@ljharb in this case, i didn't think there was a difference between:

const test = require('tape').test;

and:

let test = require('tape');

i've tried your suggestion, and it still fails for me. does it pass for you?

[jtlapp]

.plan(count) is how tape supports asynchronous tests. Without this, no test could be known to have finished until the program exits; but then at exit tape won't know whether all the intended tests actually ran. Besides, it's not clear that all test output could be generated during the exit process.

[ljharb]

Tests must all be scheduled synchronously - for your use case I'd recommend wrapping the entire file in a single test call so that tape knows to wait.

[simonhac]

thanks @jtlapp my example above does use .plan(count).

@ljharb, thanks for your response:

Tests must all be scheduled synchronously

i asynchronously schedule tests when use data driven test suites. i've found that this works so long as the scheduling is done within a synchronously initiated 'dummy' test. ie. your suggestion of wrapping the test scheduler in a good workaround.

from searching the issues in this project, it looks like this problem has caught quite a few and is difficult to track down. (with async calls there's always the chance of non-determinism.) i'd suggest the following:

• update documentation to prominently explain the issue and the work around, or
• modify tape so that it doesn't exit until all tests have completed, or failing that,
• modify tape to fail any test that's scheduled asynchronously when there are no running tests.

the second option is my preferred.

[jtlapp]

I was trying to explain why your options 2 and 3 are not possible.

[simonhac]

thanks @jtlapp -- i don't understand why options 2 & 3 are not possible. at least with option 3, couldn't tape detect that it has already exited and print out an explanation for failing the async'ly scheduled test?

the current behaviour feels obscure for someone not into the implementation details.

[jtlapp]

I just tried to write a lengthy explanation and found you correct and myself incorrect, @simonhac. I was actually defending tap's behavior, not tape's behavior. (I stopped using tape a while ago.) tap hangs until the test completes, which I find more reasonable, since you never know if a SIGINT or something is supposed to fire out of the blue to complete the test. It also ensures that tests run sequentially, should each be setting up and tearing down the same database or directory -- no test is done, no subsequent test is run, until the plan count is reached or end() is called.

I'm now siding with you, @simonhac. This appears to be another artifact of tape's attempt to support a test runner that can run multiple test files simultaneously. (The tape command can complete running a test suite before all the tests have run, because the program will exit if all loaded tests have finished, even if all test files have not yet been loaded.)

[m59peacemaker]

I think I'm having this problem as well.

tape "*.test.js" "lib/*.test.js"

Every few times I run it, some of the tests don't run and it says some tests exited without ending. I need the multiple globs to avoid running tests under node_modules. Is there another way?

[jtlapp]

Try replacing glob with glob.sync at this line.

Change from...

glob(arg, function (err, files) {
    files.forEach(function (file) {
        require(resolvePath(cwd, file));
    });
});

...to...

glob.sync(arg).forEach(function(files) {
    files.forEach(function (file) {
        require(resolvePath(cwd, file));
    });
});

(I just threw that together now, so there may be a bug in there.)

[m59peacemaker]

Close! This did the trick:

    glob.sync(arg).forEach(function(file) {
        require(resolvePath(cwd, file));
    });

So... should that be a PR? I don't know what else that might affect. Tape's tests still pass after that change, though.

[jtlapp]

It'll slow down test suites that do manage to run in parallel.

[feross]

PR to fix this issue: #374