Skip to content

vm: timeout raised by vm.runInContext breaks console.log #34678

Open
@bchabrier

Description

@bchabrier

What steps will reproduce the bug?

I have created the following snippet to reproduce the problem:

const vm = require('vm');

let context = vm.createContext({ process: process });

let countErr = 0;
while (process.stdout._writableState.bufferedRequestCount == 0 && countErr < 10) {
    try {
        vm.runInContext("while (true) {process.stdout.write('');}",
            context,
            { timeout: 100 });
    } catch (err) {
        countErr++;
        console.warn(err.message);
    }
}
console.error("stdout bufferedRequestCount:", process.stdout._writableState.bufferedRequestCount);
console.error('Needed to raise that many timeouts to show the problem:', countErr);
console.log('Log in main still working'); // after some timeouts, this line does not print anymore
console.error("The previous line should be 'Log in main still working', if it is not, stdout seems to be broken...");

How often does it reproduce? Is there a required condition?

Issue happens systematically, after a couple of timeouts raised (not always the same number)

What is the expected behavior?

Script execution timed out.
Script execution timed out.
Script execution timed out.
Script execution timed out.
Script execution timed out.
Script execution timed out.
Script execution timed out.
Script execution timed out.
Script execution timed out.
Script execution timed out.
stdout bufferedRequestCount: 0
Needed to raise that many timeouts to show the problem: 10
Log in main still working
The previous line should be 'Log in main still working', if it is not, stdout seems to be broken...

What do you see instead?

Script execution timed out.
Script execution timed out.
Script execution timed out.
stdout bufferedRequestCount: 4564
Needed to raise that many timeouts to show the problem: 3
The previous line should be 'Log in main still working', if it is not, stdout seems to be broken...

Additional information

Some points that can be helpful:

  • The issue is raised with vm.runInContext, vm.runInNewContext, vm.runInThisContext.
  • The same issue happens with process.stderr, so it's not specific to process.stdout.
  • No event (error, drain...) is emitted by process.stdout.
  • I could figure out that, when a timeout is raised (might not be the first one), process.stdout starts to buffer the process.stdout.write requests and process.stdout.write calls will return false. When too many, process.stdout will eventually enter in needDrain mode. However, the drain event is never emitted. It looks like something prevents the data to be output on the terminal, the buffer of process.stdout is never processed, leaving process.stdout in a needDrain mode forever.

Note that the actual code I want to run in my project is not exactly the snippet. It has no infinite loop, it just runs a piece of code that makes use of console.log to trace different steps, and it happens regularly that it timeouts. Hence, my project requires the capability to use console.log, have a timeout raised, and still be able to use console.log after that.

Any idea about this? Any workaround?

Metadata

Metadata

Assignees

No one assigned

    Labels

    consoleIssues and PRs related to the console subsystem.stdioIssues and PRs related to stdio.vmIssues and PRs related to the vm subsystem.

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions