`jasmine.execute()` never resolves since v3.6.2

[nicojs]

The implementation of jasmine.execute() broke in v3.6.2.

Jasmine core's execute function is called with a callback argument here:

https://github.com/jasmine/jasmine-npm/blob/b5ff543e91d4efd8d99f5dfa2731fd4ce777bc59/lib/jasmine.js#L271

However, the currently released version of jasmine-core (v3.6.0) does not support a callback

https://github.com/jasmine/jasmine/blob/d51da1880870ed07b2c898a261e96524e99ecc49/src/core/Env.js#L708

It was merged in on 2 Sept, but not released yet: https://github.com/jasmine/jasmine/commit/00feef8632a8b59ee44eb12aa28d9c9810b72c86

[nicojs]

This actually also results in a memory leak. There is no way of cleaning closures because they will always remain reachable via the never resolved promise.

[sgravrock]

Thanks for the report. I see the problem, but I’m having trouble understanding the impact given that jasmine.execute didn’t return a promise prior to 3.6.2. Do you have an example that works in previous versions but leaks memory or otherwise misbehaves in 3.6.2?

[nicojs]

Sure, great questions.

but I’m having trouble understanding the impact given that jasmine.execute didn’t return a promise prior to 3.6.2

I'm the maintainer of Stryker, the mutation testing framework for JavaScript and friends. We're supporting Jasmine via the programmatic API.

Our simplified Jasmine adapter looks like this:

const Jasmine = require('jasmine');

async function run() {
    try {
        let resolve;
        const runPromise = new Promise((res) => {
            resolve = res;
        });
        const jasmine = new Jasmine();
        jasmine.loadConfigFile('./spec/support/jasmine.json');
        jasmine.exit = () => {
            console.log('exit called');
        };
        const tests = [];
        const reporter = {
            specDone(result) {
                tests.push(tests.push(result));
            },
            jasmineDone() {
                resolve();
            }
        }
        jasmine.env.addReporter(reporter);

        jasmine.execute();
        await runPromise;
        return { state: 'success', tests };
    }
    catch (err) {
        return { state: 'error', err };
    }
}

run().then(res => console.log('res: ', res)).catch(err => console.error('err: ', err));

We want to handle all kinds of input a user might have, so we also have a test for invalid JavaScript:

// Player.spec.js
this is invalid javascript;

In 3.6.1, this error is perfectly handled:

$ node run-jasmine.js 
res:  {
  state: 'error',
  err: /home/nicojs/github/jasmine-lib-test/spec/helpers/jasmine_examples/SpecHelper.js:1
  this should be a runtime error
       ^^^^^^

But in 3.6.2, this error results in:

node run-jasmine.js 
(node:1798) UnhandledPromiseRejectionWarning: /home/nicojs/github/jasmine-lib-test/spec/helpers/jasmine_examples/SpecHelper.js:1
this should be a runtime error
     ^^^^^^

SyntaxError: Unexpected identifier

Do you have an example that works in previous versions but leaks memory or otherwise misbehaves in 3.6.2?

One thing Stryker does is reuse test runner worker processes. This means that we run Jasmine in the same process on the same project over and over again. We do this by clearing the user project modules from the node cache. This works fine in 3.6.2, but in 3.6.3 this results in an out-of-memory (OOM) error.

We're using a small test to reproduce this:

// big-text.spec.js
const { text } = require('../../lib/big-text');

describe('Big text', () => {
  it('should contain i', () => {
    if (text.indexOf('i') === -1) {
      throw new Error();
    }
  });
});

// big-text.js

// Change the text each iteration to prevent nodejs from optimizing it into one value on the heap
if (!global.n) {
  global.n = 500000;
}
module.exports.text = new Array(global.n++).fill('i').join(',');

Then we run our jasmine-runner adapter on this project 20 times with --max-old-space-size=32. This should be fine if indeed clearing big-text.js from node cache is enough to make the module.exports.text variable unreachable and, thus, garbage collectible.

In 3.6.1, this worked fine:

[...]
Iteration  1
Randomized with seed 38639
Started
.

1 spec, 0 failures
Finished in 0.002 seconds
Randomized with seed 38639 (jasmine --random=true --seed=38639)
exit called
res:  [
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] },
  { state: 'success', tests: [ [Object], 1 ] }
]

Since 3.6.3, this test results in:

[...]
Iteration  1

<--- Last few GCs --->

[2969:0x4cee4f0]      954 ms: Mark-sweep 31.6 (33.8) -> 31.6 (33.8) MB, 5.4 / 0.0 ms  (average mu = 0.334, current mu = 0.006) allocation failure scavenge might not succeed
[2969:0x4cee4f0]      962 ms: Mark-sweep 31.6 (33.8) -> 31.5 (33.5) MB, 8.4 / 0.0 ms  (average mu = 0.167, current mu = 0.002) last resort GC in old space requested
[2969:0x4cee4f0]      968 ms: Mark-sweep 31.5 (33.5) -> 31.5 (33.5) MB, 5.3 / 0.0 ms  (average mu = 0.103, current mu = 0.002) last resort GC in old space requested

<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x13cf019]
Security context: 0x1a582fd808d1 <JSObject>
    1: join [0x1a582fd955f9](this=0x3558f7972641 <JSArray[500019]>,0x011ecc7c6d31 <String[#1]: ,>)
    2: /* anonymous */ [0x3558f794bbb9] [/home/nicojs/github/jasmine-lib-test/lib/jasmine_examples/Player.js:6] [bytecode=0x2a3e10b9be39 offset=95](this=0x3558f797ff71 <Object map = 0xd35a6a80439>,0x3558f797ff71 <Object map = 0xd35a6a80439>,0x3558f794d0e9 <JSFunctio...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory

I've attached the example here. Run with --max-old-space-size=32 run-jasmine.js.

jasmine-lib-test.zip

[sgravrock]

Thanks for the detailed repro, and I'm sorry for not getting back to you sooner.

It looks like there might be a couple of different things going on here. If I patch your example to pin to the current main of jasmine-core and also to await the promise returned from jasmine.execute as shown below (note that I'm using Yarn), then the case where a spec file contains a syntax error behaves the way you expect:

$ node --max-old-space-size=32 run-jasmine.js
Iteration  20
[...]
res:  [
  {
    state: 'error',
    err: /Users/steve/downloads/jasmine-lib-test/spec/jasmine_examples/PlayerSpec.js:1
    a syntax error
      ^^^^^^

    SyntaxError: Unexpected identifier
        at wrapSafe (internal/modules/cjs/loader.js:992:16)
        at Module._compile (internal/modules/cjs/loader.js:1040:27)
        at Object.Module._extensions..js (internal/modules/cjs/loader.js:1097:10)
        at Module.load (internal/modules/cjs/loader.js:941:32)
        at Function.Module._load (internal/modules/cjs/loader.js:782:14)
        at Module.require (internal/modules/cjs/loader.js:965:19)
        at require (internal/modules/cjs/helpers.js:88:18)
        at Loader.requireShim [as require_] (/Users/steve/downloads/jasmine-lib-test/node_modules/jasmine/lib/loader.js:21:3)
        at /Users/steve/downloads/jasmine-lib-test/node_modules/jasmine/lib/loader.js:14:12
        at new Promise (<anonymous>)
  },
[... lots more...]

But without the syntax error, I still see the OOM crash. I'm not sure if that means that something is still broken, or if something is missing from the example. Can you check whether pinning to the main branch of jasmine-core and awaiting the promise as below solves the problem for you?

diff -u jasmine-lib-test original/package.json jasmine-lib-test/package.json
--- jasmine-lib-test original/package.json  2020-11-02 08:00:32.000000000 -0800
+++ jasmine-lib-test/package.json   2021-01-16 14:15:22.000000000 -0800
@@ -11,5 +11,8 @@
   "license": "ISC",
   "devDependencies": {
     "jasmine": "3.6.3"
+  },
+  "resolutions": {
+    "jasmine-core": "https://github.com/jasmine/jasmine#main"
   }
 }
diff -u jasmine-lib-test original/run-jasmine.js jasmine-lib-test/run-jasmine.js
--- jasmine-lib-test original/run-jasmine.js    2020-11-02 07:58:38.000000000 -0800
+++ jasmine-lib-test/run-jasmine.js 2021-01-16 14:15:44.000000000 -0800
@@ -24,7 +24,7 @@
         }
         jasmine.env.addReporter(reporter);

-        jasmine.execute();
+        await jasmine.execute();
         await runPromise;
         return { state: 'success', tests };
     }

[sgravrock]

Closing since I think the 3.7 release should have fixed this, and we haven't heard anything new in quite a while. Feel free to open a new issue with more information if you're still having problems.