Tests continue to fail after the first missing .end

[chrisnicola]

I'm not yet able to provide much analysis for this issue, but I'll describe the setup and the behaviour as well as I can.

Setup

Using webpack to process the files before running the tests. These are Vue tests using single-file-components, so unfortunately Webpack is a requirement at the moment. I suspect that the output format of the webpack'd test files is a possible cause of this issue.

The output from webpack is then executed using node and the tests run fine. Using the sourcemaps plugin source locations work as well for most errors. However when there is a missing t.end() I get a repeating error for all of the remaining tests.

Results

The output is below. Basically after it hits the test that fails to end it continues and reports the same error for all the following tests.

Bundle compiled, executing...
loaded
TAP version 13
# renders root element
ok 1 should have exactly one root element
# lib/avoriaz/componentStub creates component stubs by name
ok 2 Adds a named stub.
ok 3 Can add more than one stub.
ok 4 Will retain real components.
ok 5 Can override real components.
ok 6 ComponentStub.rendered is false before render() is called
ok 7 ComponentStub.rendered is true after render() is called
# parsePathTempalte
ok 8 parses './index.vue' as '/'
ok 9 parses './clients.vue' as '/clients'
ok 10 parses './clients/_id.vue' as '/clients/:id?'
ok 11 parses './clients/_name.vue' as '/clients/:name?'
ok 12 parses './clients/_id/index.vue' as '/clients/:id'
ok 13 parses './clients/_name/index.vue' as '/clients/:name'
ok 14 parses './clients/_id/accounts.vue' as '/clients/:id/accounts'
ok 15 parses './my_account.vue' as '/my_account'
ok 16 parses './my-account.vue' as '/my-account'
# parseName
ok 17 parses './index.vue' as 'root'
ok 18 parses './clients.vue' as 'clients'
ok 19 parses './clients/_id.vue' as 'clients/:id'
ok 20 parses './clients/_name.vue' as 'clients/:name'
ok 21 parses './clients/_id/index.vue' as 'clients/:id'
ok 22 parses './clients/_name/index.vue' as 'clients/:name'
ok 23 parses './clients/_id/accounts.vue' as 'clients/:id/accounts'
ok 24 parses './my_account.vue' as 'my_account'
ok 25 parses './my-account.vue' as 'my-account'
# generateRoute
ok 26 Generates a path for the route if there is no route.path.
ok 27 Generates a name for the route if there is no route.name.
ok 28 Sets the component for the route.
ok 29 Uses component route.path if there is one
ok 30 Uses component route.name if there is one.
# buildRoutes
ok 31 creates 2 routes for two non-child keys in the context
ok 32 creates a nested child route
not ok 33 test exited without ending
  ---
    operator: fail
    at: process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
    stack: |-
      Error: test exited without ending
          at Test.assert [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:212:54)
          at Test.bound [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test.fail (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:277:10)
          at Test.bound [as fail] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test._exit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:178:14)
          at Test.bound (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at process.<anonymous> (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/index.js:86:19)
          at emitOne (events.js:115:13)
          at process.emit (events.js:210:7)
          at process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
  ...
not ok 34 test exited without ending
  ---
    operator: fail
    at: process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
    stack: |-
      Error: test exited without ending
          at Test.assert [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:212:54)
          at Test.bound [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test.fail (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:277:10)
          at Test.bound [as fail] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test._exit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:178:14)
          at Test.bound (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at process.<anonymous> (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/index.js:86:19)
          at emitOne (events.js:115:13)
          at process.emit (events.js:210:7)
          at process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
  ...
not ok 35 test exited without ending
  ---
    operator: fail
    at: process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
    stack: |-
      Error: test exited without ending
          at Test.assert [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:212:54)
          at Test.bound [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test.fail (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:277:10)
          at Test.bound [as fail] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test._exit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:178:14)
          at Test.bound (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at process.<anonymous> (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/index.js:86:19)
          at emitOne (events.js:115:13)
          at process.emit (events.js:210:7)
          at process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
  ...
not ok 36 test exited without ending
  ---
    operator: fail
    at: process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
    stack: |-
      Error: test exited without ending
          at Test.assert [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:212:54)
          at Test.bound [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test.fail (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:277:10)
          at Test.bound [as fail] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test._exit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:178:14)
          at Test.bound (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at process.<anonymous> (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/index.js:86:19)
          at emitOne (events.js:115:13)
          at process.emit (events.js:210:7)
          at process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
  ...

### <removed several more repeated tests for length>

not ok 62 test exited without ending
  ---
    operator: fail
    at: process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
    stack: |-
      Error: test exited without ending
          at Test.assert [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:212:54)
          at Test.bound [as _assert] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test.fail (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:277:10)
          at Test.bound [as fail] (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at Test._exit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:178:14)
          at Test.bound (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/lib/test.js:64:32)
          at process.<anonymous> (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/tape/index.js:86:19)
          at emitOne (events.js:115:13)
          at process.emit (events.js:210:7)
          at process.emit (/Users/chrisnicola/src/wealthbar-koa-starter/node_modules/source-map-support/source-map-support.js:431:21)
  ...

1..62
# tests 62
# pass  32
# fail  30

✨  Done in 4.50s.

The stack trace is also a bit odd, in that it doesn't show the location of the test that failed to end.

[ljharb]

I would expect that when a test errors because it "exited without ending", that the test would be marked as ended, and that any successive t.end() calls are no-ops. This seems like a bug to me.

[chrisnicola]

@ljharb thanks. I'll see if I can trace it to the cause today then.

[chrisnicola]

So the problem seems to happen here during process.on('exit') which is being fired after the first test fails to call .end. It then loops through the other tests calling _exit() on each one without running them so they also report that the test exited without ending.

What I'm not clear on is why the process is exiting after the first failure.

[chrisnicola]

Ok and this code is what causes the test suite to exit. It sets up assuming that an 'end' may be called in some asynchronous code, however if that isn't the case there is nothing left for node to do so the process exits. Then that exit code runs and called _exit on the remaining tests.

A simple solution I tested initially was to a reasonable default timeout for all tests. It would seem that there is really no other way to not have undeterminable behaviour for synchronous tests that fail to call .end(). However, this runs into a new problem which is that all of the other tests get held up when the while loop exits and waits for end and they all fail and timeout as well.

I'm probably stabbing in the dark a bit at this point as I don't know this code that well but that's as far as I've got in the investigation so far.

[chrisnicola]

Hmm the problem with the default timeout is stranger than I would have expected. It also causes a timeout error to occur for all the tests that have already run. I've gone back and verified that these have all run clearTimeout and end was called, so this is really strange to me.

[chrisnicola]

Hey @ljharb sorry for the spam. I found the cause of the timeout issue. It appears that much like safeSetTimeout the clearTimeout call needs to be assigned to a local variable as well or it does not work as expected and the timeout is never actually cleared.

I'm not really sure this is the right solution for this library but I'll submit a PR anyways with what I think makes sense which is.

1. Have the timeout option choose a default value of 1000ms to ensure we can detect a missing .end() reliably and without causing the entire test suite to exit.
2. Fix the bug with clearTimeout that was preventing timeouts from successfully being cleared.

[chrisnicola]

So I've limited the change to just setting the clearTimeout global as a local. I'm not sure why I needed that, but it may have something to do with the "webpacked" output in this case.

I do think there is a larger issue with how the end of a test is detected when end is missing or the plan is incomplete. Moving to the assumption of a default timeout seems reasonable but it is a pretty big change from the current behaviour of tape right now so I don't want to make that change without further discussion.

[ljharb]

Thanks for all the research! I'll take a look at the PR.

[mantoni]

I'm running into the same issue. Here is a minimal test to reproduce:

const test = require('tape')

test('no end', (t) => {
  t.ok(true)
})

test('second', (t) => {
  t.ok(true)
  t.end()
})

This fails twice instead of once.