Generated Mocha tests (JS) sporadically fail

[iva2k]

Steps to reproduce

Performed the following steps from https://generator.feathers-plus.com/get-started/

npm i -g @feathers-plus/cli
mkdir feathers-app
cd feathers-app
feathers-plus generate options
# chosen all defaults

feathers-plus generate app
# chosen all defaults

# optional:
feathers-plus generate authentication
# chosen all defaults, except added Google/Facebook

npm start
# runs ok

Trying test:

npm test
# Sometimes fails with timeout, other times no failure

Expected behavior

Tests should always pass

Actual behavior

One of the tests might fail with timeout.

> api@0.0.0 test C:\dev\ionic3-feathersplus-try2\api.js
> npm run eslint && npm run mocha

> api@0.0.0 eslint C:\dev\ionic3-feathersplus-try2\api.js
> eslint src/. test/. --config .eslintrc.json

> api@0.0.0 mocha C:\dev\ionic3-feathersplus-try2\api.js
> mocha test/ --recursive --exit --timeout 10000

  Feathers application tests
    √ starts and shows the index page (95ms)
    404
error: Page not found {"type":"FeathersError","name":"NotFound","code":404,"className":"not-found","data":{"url":"/path/to/nowhere"},"errors":{}}
      √ shows a 404 HTML page
error: Page not found {"type":"FeathersError","name":"NotFound","code":404,"className":"not-found","data":{"url":"/path/to/nowhere"},"errors":{}}
      √ shows a 404 JSON error without stack trace
    1) "after all" hook

  'users' service
    √ registered the service

  4 passing (10s)
  1 failing

  1) Feathers application tests
       "after all" hook:
     Error: Timeout of 10000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (C:\dev\ionic3-feathersplus-try2\api.js\test\app.test.js)

npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! api@0.0.0 mocha: `mocha test/ --recursive --exit --timeout 10000`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the api@0.0.0 mocha script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     C:\Users\iivanchenko\AppData\Roaming\npm-cache\_logs\2018-07-17T23_18_29_942Z-debug.log
npm ERR! Test failed.  See above for more details.

System configuration

Using Windows7, node v8.11.2,

[iva2k]

Though it's hard to reproduce the issue, it has been known for a while.

The reason for failure is race condition described in Mocha: Mocha > Arrow Functions

BTW, feathers generate service has the same issue.

Fix

Code in describe() and it() functions in *.test.js files should be converted from '() => {...}' to 'function() {...}'

it eliminates the mentioned race condition and tests consistently pass.

[eddyystop]

I'm delighted to get clarification on this issue. Thanks!

[eddyystop]

The Mocha docs you link to states the use of arrow functions is discouraged only because arrow functions cannot access the Mocha context via this.

I can't find information relating arrow functions to race conditions. Please clarify.

[iva2k]

@eddyystop Yeah, you right, the race condition is not described on Mocha (I forgot, its been a while since I sorted this out for my use). Mocha page is very cryptic about done() and arrow functions. I inferred from that Mocha cryptogram and the issue discussion here:

SO#16607039 (see e.g. syberkitten answer)

What happens it looks like, when not having Mocha context passed, the mechanism of doing done() behind the scenes is broken (when there's no explicit done() coded). So either code done() carefully everywhere, return Promise everywhere the test is async, or use function() {} instead of () => {}. I prefer the latter, as its the easiest (no need to rewrite tests).

[eddyystop]

Arrow functions removed in tests.

Fix published as f+/cli v0.4.17 running generator v0.2.23.

Please run your tests again and report results, as I was not experiencing failures on Ubuntu.

[iva2k]

Thanks! I did a quick try:

npm install -g @feathers-plus/cli
mkdir feathers-app
cd feathers-app
feathers-plus generate options
# chosen all defaults, except "Generate TypeScript code?" Case1: No (with JS), Case2: Yes (with TS)
feathers-plus generate app
# chosen all defaults
npm test

Unfortunately... Case1 JS Failed (1 of 5 runs) Case2 TS Failed (1 of 4 runs)

...same timeout error. Hm, I went back to my other project with dozen tests, and got it failing sometimes with same timeout. It did not have that for very long time since I changed fat arrows. Perhaps some changes in latest node? mocha? feathers? hard to trace.

For sure removal of fat arrows is good, e.g. app.test.?s was using "this.server" inside of arrowed describe(). See e.g. this good article on what "this" actually is with different arrangements: link.

I will dig more...

[iva2k]

So far what I found:

1. after() in app.test.?s is the culprit.
2. It only calls this.server.close(done). no big deal?
3. unrolling the call chain, it ends up feathers->express->http.listen().close in the guts of Node.
4. the following code can be tuned to fail always or (seemingly) never, by only adjusting the delay:

  // test/app.test.?s:
  after(function (done) {
    this.server.close( (e) => {
      setTimeout(() => {
        done(e);
      }, 100 /* <- adjust here */ );
    });
  });

Delay of 100ms fails every time. Huh? posting 'done' after the server's callback says it's done should not trip, right? 20ms and down, 200ms and up seems to mostly work without error. Very baffling result, totally unexpected behavior. But certainly it is some race condition.

I can't imagine how Mocha could be failing to receive its done callback depending on the delay. It certainly does not miss the 10000ms timeout, as this whole test runs in 300ms. I suspect Node does something unclean on Windows. I can't figure out what other signal arrives to Mocha and creates race condition with done() callback. I can think of only exceptions, but those should be caught and fail the test, not let it trip the timeout.

To close this issue I don't like to recommend inserting setTimeout for any delay as a fix - it is brittle and would fail again sometime. But I'll use it for my local workaround.

I'm out of ideas for a global fix.

[eddyystop]

I'm working on some Mocha tests which include both a client and a server.

server.close(), for example, will not close the server if there are any open connections. I'm wrapping server in the repo http-shutdown so that can destroy the connections before doing a .close().

I agree in thinking server.close() is the problem. I'm not sure the server is totally down when the callback is called.

[eddyystop]

I reverted the removal of the arrow functions. Its more important in my opinion to remain compatible with feathersjs/cli.

I'm closing this issue until we get a better understanding of the internals.

[iva2k]

Unrelated to the original issue of timeouts, the arrows in app.test.js make for interesting problem... per the article I linked above, this.server = ... puts server property into context not of Mocha, but of global. Not a very good place to store internal stuff into.

That is unexpected. The this.timeout() call used this which due to arrow function callback points at this inside the describe callback; which itself points outside because it is a callback function. When you point outside the outer function what do you get? In JavaScript this differs. If you are inside a proper function, the outside context would be a global object (Node) or window object (browser). So if we wrap our describe in a dummy function foo, we would get this === global inside each test.

function foo () {
  describe('my tests', () => {
    it('passes after 3000ms', (done) => {
      console.log('test arguments', arguments)
      console.log('this === global', this === global)
      // this.timeout(3500)
      setTimeout(done, 3000)
    })
  })
}
foo()

test arguments {}
this === global true

[eddyystop]

I'm not sure how to relate his detailed explorations to our case. I'm tempted to change the test setup to what I normally use in my own tests:

describe('Feathers application tests', () => {
  let server;

  before(function (done) {
    server = app.listen(port);
    server.once('listening', () => done());
  });

  after(function (done) {
    server.close(done);
  });

What do you think?

[iva2k]

He just explains what "this" is not what it is expected to be and shows with experiments. Just expands on the note from Mocha page.

I did local let server in feathers project too, it's much cleaner than assuming "this" belongs to the test scope.

Though in (rare) cases where this.timeout =... is used (not seen in Feathers yet), it won't work (e.g. won't change the timeout of Mocha), need to remove fat arrows.

[eddyystop]

Published as f+/cli v0.4.21 using generator v0.2.27.