Fix tests setup - ensure errors are exposed #4139

medikoo · 2017-08-22T13:24:55Z

What did you implement:

There are errors in tests which are not properly exposed, additionally due to that, some configured tests are not invoked at all.

Issue lies in not handled rejected promises, their errors are exposed only via UnhandledRejection warnings which can be seen through the tests output, but which do not force tests to fail as expected.

I didn't fix code corresponding to broken tests, I thought it's better (more efficient) if it's looked after by its authors. Due to that CI crashes, it's expected

How did you implement it:

In tests I ensured that those rejected promises are returned to mocha functions, therefore exposed as expected.

Still, more future proof solution would be to add following code to some init test script:

process.on('unhandledRejection', err => {
  throw err;
});

This will ensure that all currently (and those introduced in future) broken tests will fail same way as they do after this PR is applied.

This approach was also scheduled to be default in Node.js -> nodejs/node#12010
If you agree on that solution I may add it instead of patching individual tests, just let me know where's the best place.

How can we verify it:

Run tests

Todos:

Is this ready for review?: YES
Is it a breaking change?: NO

pmuens

Wow! That's a really nice catch!

Thanks for that @medikoo 👍

We need to fix this ASAP. Big +1 for adding a global Promise catch statement. AFAIK we had that previously, but we removed this in Oct / Nov 2016 (AFAIK it had smth. todo with invoke / invoke local). Can you remember what this was @mthenw @eahefnawy @nikgraf ?

IMHO we should re-add this ASAP. Furthermore it would be nice if we could fix the tests in this PR so that we're in a passing state after merging this

(otherwise reviewing and merging new PRs might be a nightmare).

pmuens · 2017-08-23T09:05:40Z

Looks like we already have smth. like that in place --> here.

It will execute this method. However it's not executed correctly (looks like the exit code is not set correctly).

medikoo · 2017-08-23T09:13:21Z

Looks like we already have smth. like that in place --> here.

This program is not executed (required) when testing, which probably makes sense, but then it means that process.on('unhandledRejection',... should be introduced also in some module that's invoked by tests, which one would be right?

HyperBrain · 2017-08-23T09:27:35Z

@pmuens The problem with invoke local is, that customer code is executed within the Serverless process. That means that, if the frameworks adds a specific unhandled rejection or unhandled exception handler, it must make sure that the tracker is not invoked in case of invoke local to prevent sending sensitive data, but I think that had been solved already.

The other side of this is, that the unhandled handler should in this case not interfere with handlers that the user code might have set. Imagine user code that handles them in some obscure way and just continues execution somehow.

Maybe the handler could be set conditionally in the framework, depending on the commands invoked (i.e. not for invoke local) the handler should not be set. Would this be a feasible solution, or did I miss something?

medikoo · 2017-08-23T09:37:14Z

@HyperBrain does your points also relate to tests process in any way?

I totally agree it should not be forced within Serverless in general, but there's no side effects to the users of the framework if unhandled rejections are forced to crash purely in program that runs tests (or am I missing something?)

HyperBrain · 2017-08-23T09:39:18Z

I referred to @pmuens

should be introduced also in some module that's invoked by tests,

Locally within the tests I see no problem at all. Only if the handling leaves that scope care has to be taken 😃

medikoo · 2017-08-23T10:00:46Z

Ideally this should be taken care in mocha, and it's already been proposed and discussed there:

mochajs/mocha#1926
mochajs/mocha#2640 (They even seem to be open for PR)

For a meantime we may take care of it via slight hacking, introduce bin/test with following content:

#!/usr/bin/env node

'use strict';

process.on('unhandledRejection', err => {
  throw err;
});

require('mocha/bin/_mocha');

And referring scripts to this program instead of node_modules/bin/_mocha

pmuens · 2017-08-23T12:11:55Z

Thanks for the nice conversation @HyperBrain and @medikoo 👍!

I like the solution to introduce a bin/test file and "hack" around the problem for now since this won't break any existing UX.

medikoo · 2017-08-23T15:25:37Z

@pmuens I thought it might be good to also hard code here arguments:

\"!(node_modules)/**/*.test.js\" --require=sinon-bluebird -R spec --recursive

It can work as default, so if some arguments are detected, then they're not forced

It will allow, to not have them duplicated in scripts configuration

What do you think?

pmuens · 2017-08-24T10:15:55Z

@medikoo yes, that sounds like a good enhancement! This way we'd have one place to look for / make changes 👍

medikoo · 2017-08-24T12:39:47Z

@pmuens I applied that. I've also added --no-exit to mocha setup, as without this, tests program would still be vulnerable to hidden errors issue, more info on that here -> mochajs/mocha#2879

pmuens · 2017-08-24T15:26:58Z

@pmuens I applied that. I've also added --no-exit to mocha setup, as without this, tests program would still be vulnerable to hidden errors issue, more info on that here -> mochajs/mocha#2879

Very nice! Thanks for the updates @medikoo 👍!

pmuens

Thanks for the updates @medikoo 👍 💯

I just gave this another try today and it looks pretty promising. Furthermore I added some comments while doing a code-review.

When I run it I get a pretty weird output. The result is duplicated. I've attached a screenshot which shows how it looks like on my machine after running npm test:

pmuens · 2017-08-25T09:01:31Z

lib/Serverless.test.js


    afterEach(() => {
+      if (!serverless.utils.logStat.restore) return;


Why is this needed?

As serverless.init() fails, stubs are not initialized therefore there's no restore methods.
Without this, there will be additional crash in afterEach.

Still it's indeed not needed when serverless.init() succeeds, so assuming we're fix it, we can indeed remove it, as it's just extra noise

pmuens · 2017-08-25T09:02:51Z

lib/classes/Utils.test.js

@@ -21,7 +21,7 @@ describe('Utils', () => {
  beforeEach(() => {
    serverless = new Serverless();
    utils = new Utils(serverless);
-    serverless.init();
+    return serverless.init();


Shouldn't we put this right at the beginning of the beforeEach block like it's done below?

You mean to move it before utils = new Utils(serverless); line? It can't be starting line here, as there's no serverless instance yet

pmuens · 2017-08-25T09:02:59Z

lib/classes/Utils.test.js


    afterEach(() => {
+      if (!segment.track.restore) return;


Why is this needed?

Same case as commented above

pmuens · 2017-08-25T09:03:17Z

lib/utils/fs/writeFile.test.js

@@ -16,7 +16,7 @@ describe('#writeFile()', function () {
  this.timeout(0);
  beforeEach(() => {
    serverless = new Serverless();
-    serverless.init();
+    return serverless.init();


Shouldn't we move this to the beginning of the beforeEach block?

Here similarly, at beginning of this beforeEach block, there's no serverless instance

pmuens · 2017-08-25T09:03:27Z

lib/utils/fs/writeFileSync.test.js

@@ -11,7 +11,7 @@ describe('#writeFileSync()', () => {

  beforeEach(() => {
    serverless = new Serverless();
-    serverless.init();
+    return serverless.init();


Shouldn't we move this to the beginning of the beforeEach block?

medikoo · 2017-08-25T09:39:57Z

Furthermore I added some comments while doing a code-review.

@pmuens Thanks, I replied to comments

When I run it I get a pretty weird output. The result is duplicated. I've attached a screenshot which shows how it looks like on my machine after running npm test:

This is result of another unhandled rejection that got in after I proposed this PR (must came in after merge with master).

I fixed those with d6b29ab

Now, concerning weird output by mocha. The crashing now unhandled rejections are picked by mocha as it observes internally uncaughtException events. Still the mocha reports generated for that errors are not that reliable.
I propose then to force unanhandledRejections to crash process the hard way (so they're not picked by mocha), then the error message is eminent and should leave no doubt, e.g. in this case:

It's actually how I picked all of them cleanly, for this PR. We can achieve it by, clearing all uncaughtException listeners prior throwing exception:

process.on('unhandledRejection', err => {
  delete process._events.uncaughtException;
  throw err;
});

pmuens

Hey @medikoo,
first of all: Thanks for replying to the comments and pushing some fixes 👍.

I just took a deeper dive into this PR today since I wanted to fix all the tests so that we can merge it ASAP and have a solid test suite again.

However unfortunately the tests which were updated in this PR fail due to a timeout (e.g. should load serverless.yaml from filesystem). I tried to work out what the main reason is, but couldn't wrap my head around it since all the Promises are returned 🤔

Do you have any clue what could be wrong here? Thanks in advance!

medikoo · 2017-09-01T10:22:37Z

@pmuens interesting, I do not observe it on my side.

I've also merged it with master and pursued repository cleanup with git clean -dfx, to ensure any cache does not go in place, and still have clean exit with no timeout but 10 tests failing. (I'm on OSX v10.12.6, node: v8.4.0, npm: v4.6.1)

Do you have some changes that are maybe not pushed into this branch? Also maybe try git clean -dfx to reset repository (?)

pmuens · 2017-09-01T11:23:54Z

Hey @medikoo thanks for the reply and thanks for updating this PR 👍

The failing tests on my local machine are the same which are also failing on Travis (https://travis-ci.org/serverless/serverless/jobs/270768136#L2970). I tried to dig deeper into that (used it.only to only run e.g. the should load serverless.yaml from filesystem test) and it turns out that the tests timeout when I only run one of them, so it looks like there's something off with the Promise resolving 🤔

HyperBrain · 2017-09-01T12:16:03Z

bin/test

+
+'use strict';
+
+process.on('unhandledRejection', err => {


I think this is wrong for the test suite.

The problem here is, that it might prevent chai from testing rejections correctly. The tests and the run code must not set any unhandledRejection handler - more exactly, it must not turn rejections into exceptions.

It is very important that chai-as-promised continues after receiving an exception, because for .to.be.rejectedWith() tests the rejection will not be detected anymore by chai. This fails currently:

return expect(myFunctionThatShouldReject()) .to.be.rejectedWith(/my error message/);

@HyperBrain this is about unhandled promise rejections, so ones not handled, either by chai-as-promised or mocha or anything else.

What's in your example is promise that's obviously handled (passed to expect which via rejectedWith is handled by chai-as-promised), you can easily validate that by e.g. adding test as:

it.only('test', () => expect(Promise.reject(new Error('Rejection'))).to.be.rejectedWith('Rejection'));

It'll pass as expected, and it won't be emitted as unhandled rejection.

Example of unhandled rejection would be a promise not handled by any entity, so: not passed to any promise processing function and not returned to any promise processing consumer, as e.g.:

it.only('test', () => { Promise.reject(new Error('Rejection')); });

medikoo · 2017-09-01T12:52:14Z

I tried to dig deeper into that (used it.only to only run e.g. the should load serverless.yaml from filesystem test) and it turns out that the tests timeout when I only run one of them, so it looks like there's something off with the Promise resolving 🤔

@pmuens It's interesting, as again I cannot reproduce that. Can you post diff of your changes against this branch?

In my case when I have it.only just on should load serverless.yaml from filesystem (so just this single test is run. It passes (and no timeout) all is fine.

I actually need to add it.only to prior test: should load serverless.yml from filesystem to have the following should load serverless.yaml from filesystem test fail. Still it happens with no timeout you observe

So e.g. after applying following diff:

diff --git a/lib/classes/Service.test.js b/lib/classes/Service.test.js
index b101845c..3f0abbfa 100644
--- a/lib/classes/Service.test.js
+++ b/lib/classes/Service.test.js
@@ -123,7 +123,7 @@ describe('Service', () => {
       return expect(noService.load()).to.eventually.resolve;
     });
 
-    it('should load serverless.yml from filesystem', () => {
+    it.only('should load serverless.yml from filesystem', () => {
       const SUtils = new Utils();
       const serverlessYml = {
         service: 'new-service',
@@ -181,7 +181,7 @@ describe('Service', () => {
       });
     });
 
-    it('should load serverless.yaml from filesystem', () => {
+    it.only('should load serverless.yaml from filesystem', () => {
       const SUtils = new Utils();
       const serverlessYml = {
         service: 'new-service',

I have test output as:

I run npm run test-bare, but exactly same way test fails with coverage overhead when running npm test

pmuens · 2017-09-01T16:08:25Z

Thanks for taking a deep dive into that @medikoo 👍 💯

I'm running your branch with 0 changes. I too get the error with the missing Plugin, but only when I run multiple tests. If I only run on with it.only I get a timeout 🤔.

BTW. I'm running it on Linux (in Docker).

HyperBrain · 2017-09-03T11:51:27Z

@medikoo @pmuens I did a git bisect over the range [1.12.1, master] to find the commit that introduced the timeouts in the unit tests. The bisect ended up with the following commit:

git.exe bisect bad

7664c2dfedfb9c529321dcd3584c70a7dd74188b is the first bad commit
commit 7664c2dfedfb9c529321dcd3584c70a7dd74188b
Author: Alex DeBrie <alexdebrie1@gmail.com>
Date:   Mon Aug 14 22:05:23 2017 +0000

Add FrameworkId to stats

:040000 040000 2e1249a87866d36cfe0a6dba9e0ee4add397fb23 d0a79267a10c8e609de5ea3d4496b668e8a2c651 M    lib

Success (813 ms @ 9/2/2017 12:11:58 AM)

I verified that with the commit immediately before, the unit tests still worked on my local Ubuntu, and this commit leads to timeouts for nearly all file operation tests.

@pmuens identified the PR containing the commit as: #4087

Imo we should analyze it and fix this issue first, before continuing to apply further (and maybe not really needed) fixes to the unit tests, so that we really improve them.

Any thoughts?

pmuens · 2017-09-04T06:31:36Z

Thanks for taking the time to bisect this @HyperBrain 👍

Imo we should analyze it and fix this issue first, before continuing to apply further (and maybe not really needed) fixes to the unit tests, so that we really improve them.

Yes, I 100% agree. Let's fix this first and then continue (if necessary). I'll take a look into this today. Would be super nice if we could get the tests fixed ASAP so that we can merge this and have a reliable test suite again!

pmuens · 2017-09-04T07:22:56Z

So I think I figured out what broke the tests here.

In the tests for Service.test.js we're calling init() (from lib/Serverless.js) for some weird reason. This results in a problem with the function which generates the cache file for the Plugins in the PluginManager class (usually we'd stub this out). I've removed the unnecessary call to init() and the tight coupling here. Now only the Service related functionality is tested in isolation.

Some tests are still failing. I'm looking into those right now...

medikoo · 2017-09-04T07:48:49Z

@pmuens it's quite puzzling I'm not able to reproduce the timeout issue on my setup.

You say you only experience it when you add .only to some test (so only this test is run). Can you post me a diff against this branch, which I can apply to exactly reproduce the setup that ends with timeout on your side?

Also on which version of node.js and linux you're observing that? I assume that it's npm v5 with dependencies installed up to package-lock.json?

pmuens

Alright. So I think all the tests have been fixed 👍

Thanks for all the hard work on this one @medikoo and @HyperBrain 💪

I'll merge it once the build passes.

pmuens · 2017-09-04T12:50:16Z

@medikoo thanks for you comment (saw it now after reading through my E-Mails).

🤔 that's super odd. @HyperBrain also faced the timeout issues. Maybe it was a race condition? I've fixed all the tests in the meantime and they should be quite stable right now.

Thanks for for getting this started and your work on this PR @medikoo 👍 💪

Ensure errorneous calls are properly exposed

5dce256

pmuens self-requested a review August 22, 2017 15:00

pmuens added the stage/in-review label Aug 22, 2017

pmuens reviewed Aug 23, 2017

View reviewed changes

medikoo added 2 commits August 24, 2017 13:05

Merge branch 'master' into fix-tests

dbb4974

Introduce test program with exposed unhandled rejections

ea7c732

pmuens suggested changes Aug 25, 2017

View reviewed changes

Fix promises handling in AwsInvokeLocal tests

d6b29ab

medikoo mentioned this pull request Aug 25, 2017

lib,src: exit process on unhandled promise rejection cleanup nodejs/node#12010

Closed

4 tasks

Merge branch 'master' into fix-tests

697d42d

pmuens reviewed Sep 1, 2017

View reviewed changes

Merge branch 'master' into fix-tests

ce1f619

HyperBrain reviewed Sep 1, 2017

View reviewed changes

Merge remote-tracking branch 'medikoo/fix-tests' into fix-tests

ff8194c

Fix Service class tests

6ee4cd4

pmuens added 2 commits September 4, 2017 09:42

Fix Utils class tests

a05bc33

Fix file-writing tests

a93358c

pmuens added 5 commits September 4, 2017 09:59

Fix invokeLocal tests

bcf3a31

Fix Serverless class tests

466e886

Fix failing Utils class tests

907c16d

Update test for remainingTimes to be less strict about the time

1121a8d

Fix failing test to work on Windows

01efc5d

pmuens added this to the 1.22 milestone Sep 4, 2017

pmuens approved these changes Sep 4, 2017

View reviewed changes

pmuens merged commit a43ffcb into serverless:master Sep 4, 2017

medikoo mentioned this pull request Sep 12, 2017

lib,src: eagerly exit process on unhanded promise rejections nodejs/node#12734

Closed

4 tasks

horike37 mentioned this pull request Oct 5, 2017

Error: Unit tests have been faild on Travis #4350

Closed


		afterEach(() => {
		if (!serverless.utils.logStat.restore) return;

Fix tests setup - ensure errors are exposed #4139

Fix tests setup - ensure errors are exposed #4139

Conversation

medikoo commented Aug 22, 2017 • edited

What did you implement:

How did you implement it:

How can we verify it:

Todos:

pmuens left a comment

Choose a reason for hiding this comment

pmuens commented Aug 23, 2017

medikoo commented Aug 23, 2017 • edited

HyperBrain commented Aug 23, 2017 • edited

medikoo commented Aug 23, 2017 • edited

HyperBrain commented Aug 23, 2017

medikoo commented Aug 23, 2017

pmuens commented Aug 23, 2017

medikoo commented Aug 23, 2017

pmuens commented Aug 24, 2017 • edited

medikoo commented Aug 24, 2017

pmuens commented Aug 24, 2017 • edited

pmuens left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

medikoo commented Aug 25, 2017 • edited

pmuens left a comment • edited

Choose a reason for hiding this comment

medikoo commented Sep 1, 2017

pmuens commented Sep 1, 2017 • edited

HyperBrain Sep 1, 2017 • edited

Choose a reason for hiding this comment

medikoo Sep 1, 2017 • edited

Choose a reason for hiding this comment

medikoo commented Sep 1, 2017

pmuens commented Sep 1, 2017

HyperBrain commented Sep 3, 2017 • edited

pmuens commented Sep 4, 2017 • edited

pmuens commented Sep 4, 2017

medikoo commented Sep 4, 2017

pmuens left a comment • edited

Choose a reason for hiding this comment

pmuens commented Sep 4, 2017

medikoo commented Aug 22, 2017 •

edited

medikoo commented Aug 23, 2017 •

edited

HyperBrain commented Aug 23, 2017 •

edited

medikoo commented Aug 23, 2017 •

edited

pmuens commented Aug 24, 2017 •

edited

pmuens commented Aug 24, 2017 •

edited

medikoo commented Aug 25, 2017 •

edited

pmuens left a comment •

edited

pmuens commented Sep 1, 2017 •

edited

HyperBrain Sep 1, 2017 •

edited

medikoo Sep 1, 2017 •

edited

HyperBrain commented Sep 3, 2017 •

edited

pmuens commented Sep 4, 2017 •

edited

pmuens left a comment •

edited