tap intermittently fails 1 test

[mreinstein]

When I invoke my test manually from the command line à la node test/sequence-buffer.js, The tap output consistently indicates success on all tests.

When I run my tests via ./node_modules/.bin/tap test

I intermittently get this error:

test/sequence-buffer.js ..1..0 # no tests found
1..0 # no tests found
test/sequence-buffer.js ......................... 1578/1579
  sequence_buffer
  not ok test count !== plan
    +++ found                                                           
    --- wanted                                                          
    -1                                                                  
    +1578                                                               
    results:
      ok: false
      count: 1578
      pass: 1578
      fail: 1
      bailout: false
      todo: 0
      skip: 0
      plan:
        start: null
        end: null
        skipAll: false
        skipReason: ''
        comment: ''
      failures:
        - tapError: no plan

Different runs also produce a different number of asserts that are run:

test/sequence-buffer.js ......................... 1651/1652

test/sequence-buffer.js ......................... 1568/1569

And then other times, the tests all pass. Mostly failure though. Is this a race condition?

[mreinstein]

the offending test https://github.com/mreinstein/reliable.io.js/blob/master/test/sequence-buffer.js

[mreinstein]

downgrading to [email protected] fixed the problem for me. This issue started in 11.0 and up.

[mreinstein]

false alarm, it's still broken on 10.7.3. I apparently when I ran it I had 20 successes in a row by chance, then it failed on travis-ci the 21st time. forehead slap

[isaacs]

Can you run the test with tap test/sequence-buffer.js -C to get the raw TAP output?

It looks like the problem is that your program is ending without finishing the test, or not flushing all the output, resulting in a truncated TAP stream.

[mreinstein]

here's a build failing on travis with tap test -C

https://travis-ci.org/mreinstein/reliable.io.js/builds/341762990

[isaacs]

Ok, so, yeah, as I suspected, the process is just exiting without that test being finished.

        ok 7160 - should be equal
        ok 7161 - should be equal
    # time=5958.959ms
    # test count(3) != plan(null)
    # failed 1 of 3 tests
        # test count(7161) != plan(null)
        # failed 1 of 7161 tests
not ok 2 - test/endpoint.js # time=6378.771ms
  ---
  timeout: 30000
  file: test/endpoint.js
  command: /home/travis/.nvm/versions/node/v8.9.4/bin/node
  args:
    - test/endpoint.js
  stdio:
    - 0
    - pipe
    - 2
  cwd: /home/travis/build/mreinstein/reliable.io.js
  failures:
    - tapError: no plan
  exitCode: 0
  ...

I'm not sure why it's not erroring more usefully though.

Is it possible that the program is calling process.exit() explicitly somewhere?

[mreinstein]

I've grepped the code and don't see process.exit() called directly in any of my code. As for modules I'm only using [email protected] and [email protected]... perhaps one of them could be calling it.

[isaacs]

Ok, yeah, there's definitely something odd going on here. Simpler repro case:

const t = require('tap')
t.test('numbers', t => {
  for (let i = 0; i < 2000; i++) {
    t.pass('a number is ' + i.toLocaleString())
  }
  t.end()
})

I'll keep digging. Thanks for finding this!

[mreinstein]

Thanks for finding this!

I'm just glad it wasn't something obvious and stupid on my part. I'm frequently terrified when opening issues in any tracker. :0

[isaacs]

Thanks, bisect.

Thanks a lot. Super helpful there.

Ok, I continue to dig.

ee2cc44e6bdc97a6a1765e2bf34fb1f34359e9b6 is the first bad commit
commit ee2cc44e6bdc97a6a1765e2bf34fb1f34359e9b6
Author: isaacs <[email protected]>
Date:   Mon Jul 3 08:54:34 2017 -0700

    tap: rewrite to class and arrows

:040000 040000 7594326d6b3b4f8779968bf005789dc660ce7660 0a971acd764f42f614b7ae7d184f0a8acc27444e M	lib

[mreinstein]

wow that's surprisingly far back in the commit history

[isaacs]

Thanks! That was a satisfying bug to track down. Not obvious at all, until I read through the ee2cc44 commit.

For anyone following along at home, note that () => {} functions don't have an arguments free var.

[mreinstein]

awesome! I wonder if this was impacting other people as well, and might reduce the number of false postive test failures across the whole npm ecosystem.

thanks for the fix! 🥇 👍