vm: fix race condition with timeout param

[laverdet]

This fixes a race condition in the watchdog timer used for vm timeouts. The condition would terminate the main stack's execution instead of the code running under the sandbox.

This also fixes the displayErrors parameter in the runIn... family of functions.

Checklist

• make -j4 test (UNIX), or vcbuild test (Windows) passes
• tests and/or benchmarks are included
• commit message follows commit guidelines

Affected core subsystem(s)

• vm

Notes

The code dealing with displayErrors was dead. When this module was first written it looked like this:

if (try_catch.HasCaught() && try_catch.HasTerminated()) {
  V8::CancelTerminateExecution(args.GetIsolate());
  return ThrowError("Script execution timed out.");
}

if (result.IsEmpty()) {
  // Error occurred during execution of the script.
  DisplayExceptionLine(try_catch.Message());
  try_catch.ReThrow();
  return;
}

But 55b87c0 modified the first if in such a way that the second if would never be true. So I went ahead and fixed that while I was in there, but that caused a bunch of errors in the repl tests because the output changed. I disabled displayErrors in the repl because the output isn't too useful in that context anyway.

[matt-kruse]

I just came here looking for someone talking about the problem I'm experiencing. See the code below - timeout exceptions only get caught intermittently. Is this a symptom of the problem you fixed, or is this a different issue?

const vm = require('vm');
const timeout = new vm.Script(`while(1){console.log('x');}`);
try {
	timeout.runInNewContext( {"console":console} , {timeout:10} );
}
catch(e) {
	// This should catch a timeout exception, but instead Node just exits.
	// It catches about 5% of the runs successfully.
	// if I remove the try/catch, the exception gets thrown all the way up.
	console.log(e);
}
console.log("done");

[laverdet]

@matt-kruse yes your issue is fixed by this patch :)

edit: wait no that may be a different issue

edit2: I have an idea of what is causing your problem. The timeout parameter will always just terminate execution of the currently running JS code, even if you are called into core nodejs code. After a quick look at _stream_writable.js I found this:

  else if (isBuf || validChunk(this, state, chunk, cb)) {
    state.pendingcb++;
    ret = writeOrBuffer(this, state, isBuf, chunk, encoding, cb);
  }

What happens if execution is terminated right after state.pendingcb++ but before writeOfBuffer(...)? You'll have a writable stream in a bad state. This might not be the exact issue causing the stream to break, but it shows how there could be a problem. There's probably countless cases of this all over the nodejs codebase, termination of execution is violating several invariants expected in those libraries.

This modification to your test demonstrates that the problem is in the writable stream library:

const vm = require('vm');
const timeout = new vm.Script(`while(1){console.log('x');}`);
try {
  timeout.runInNewContext( {"console":console} , {timeout:10} );
}
catch(e) {
  // Now this will always show the caught error
  console.error(e);
}
console.log('done'); // This sometimes will not log

Note the change of console.log -> console.error. What happens is when you terminate execution while inside of console.log it permanently destroys process.stdout. I suspect this will be a wontfix but documentation about the flaw might be a good idea.

[rodoabad]

@laverdet is that because console.error outputs to stderr while console.log outputs to stdout?

[matt-kruse]

Fantastic insight, thank you. Luckily my actual use case doesn't depend on console or stdout - this was a manufactured test case to play with vm timeouts, and I happened to use console.log().

I'd be curious to know what other landmines might exist in Node when terminating execution abruptly, but I assume as long as my vm code isn't hooking into shared streams or objects, I should be pretty safe.

[laverdet]

@rodoabad yeah sorry I should have made that clear. console.error uses a different WritableStream instance so it still works. You could also still write to stdout using: require('fs').write(1, e.stack+ '\n', function() {});

[artch]

We use this patch in production in this project. I can confirm that applying it removes a lot of random freezes on vm code timeouts.

[addaleax]

Any chance you could split the displayErrors changes out into a separate commit?

[addaleax]

Tests that are run in our CI shouldn’t generally take more than 1 second to finish… can you split this out into its own test file and reduce the timeout here?

[laverdet]

Split displayErrors fix out, and added a test for it. I also added a new line to the decorated stack because that matches the behavior of src/node.cc:1738 which is the other place stacks get a fancy arrow added.

Put the vm race test under the pummel directory because that seems like the right place?

[addaleax]

Basically LGTM, thanks for the PR!

Split displayErrors fix out, and added a test for it.

Thank you!

Put the vm race test under the pummel directory because that seems like the right place?

It is, yes… Unfortunately, we don’t run those tests in CI, but I guess here we just have to live with it.

Fresh CI: https://ci.nodejs.org/job/node-test-commit/10012/

[addaleax]

Just a tiny style nit, but we prefer 4 spaces of indentation for statement continuations – that can be fixed while merging, though

[addaleax]

I think in a previous version of this PR these were volatile… any reason why that changed?

[laverdet]

Yeah sorry I meant to leave a note about that. The volatile ended up being unnecessary. The watchdogs take a non-const reference so that's good enough to ensure the optimizer doesn't do anything fishy. Then in the dtor uv_thread_join is called which will synchronize the watchdog thread back up with the main thread.

[addaleax]

Ditto for 4-space indents. I think here we’d usually keep the v8::Isolate* isolate bit directly after the ( and align all other parameters vertically below it; but again, this is just a tiny nit and can be fixed up while landing.

[addaleax]

(ditto)

[addaleax]

You can drop the copyright header for newly added files, I think.

[laverdet]

With regard to the style changes is there a style guide out there for newcomers? The jslinter included was pretty helpful but in C++ land I found a lot of clashing styles so I just winged it. Though now that you point it out the 4-space continuation thing seems obvious.

[addaleax]

With regard to the style changes is there a style guide out there for newcomers?

Nothing except the Google styleguide which we roughly follow, but tbh I wouldn’t expect anybody to read the full text for making a contribution (e.g. I haven’t done that myself). We could probably tighten up the linter, but it doesn’t usually take people long to get used to the C++ style quirks that we have; I think the 4-space indents for continuations, lower_snake_case for local variables and preferring to align arguments vertically are the only things that trip up people on a regular basis.

Though now that you point it out the 4-space continuation thing seems obvious.

It took me a while to get used to it as well ;)

[addaleax]

Landed in 3c5bfba and e018c33, fixed up the left nits while landing. Thank you a lot for the PR!

[MylesBorins]

Should this land on v6.x?
If so it needs to be manually backported

[laverdet]

@MylesBorins the patches apply cleanly to the v6.11.1 tag for me, except for the output of a test which is a simple fix. Did you run into other issues?

[MylesBorins]

@laverdet that seems to be the conflict. Unfortunately the fix is not so simple for me to sort out... could you provide a Backport PR please

[laverdet]

@MylesBorins please see #14373 for the backport :)