Node.js Fibers and code scheduled with setTimeout leads to crash

Question

I am using Fibers to solve a problem regarding how to yield control to the event loop in node.js, pausing the execution of some synchronous code. This works well, mostly, but I encountered a strange crashing but, and I am not able to find the reason for it.

Setup

There are three process:

• A main server process, it receives code to instrument and execute. When it receives new code to execute it use child_process.fork() to spawn
• An execution process. This instruments the received code to call a specific callback from time to time to report what happened in the executed code. It then executes the code in a sandbox created by using Contextify. Sometimes these reports include incorrect location information about the line and column in the code something happens. In that case a source map is needed to map locations in the instrumented code to locations in the original code. But calculating this source map takes a significant amount of time. Therefore, before starting the execution the execution process spawns
• A source map calculation process. This just takes the original code and the instrumented code and calculates a source map. When it's done it sends the finished source map to the execution process and exits.

If the execution process needs the source map in a callback before the execution is finished, it will use Fiber.yield() to yield control to the event loop and thus pause the execution. When the execution process then receives the data it continues the execution using pausedFiber.run().

This is implemented like so:

// server.js / main process
function executeCode(codeToExecute) {
    var runtime = fork("./runtime");

    runtime.on("uncaught exception", function (exception) {
        console.log("An uncaught exception occured in process with id " + id + ": ", exception);
        console.log(exception.stack);
    });
    runtime.on("exit", function (code, signal) {
        console.log("Child process exited with code: " + code + " after receiving signal: " + signal);
    });
    runtime.send({ type: "code", code: code});
}

and

// runtime.js / execution process
var pausedExecution, sourceMap, messagesToSend = [];
function getSourceMap() {
    if (sourceMap === undefined) {
        console.log("Waiting for source map.");
        pausedExecution = Fiber.current;
        Fiber.yield();
        pausedExecution = undefined;
        console.log("Wait is over.")
    }

    if (sourceMap === null) {
        throw new Error("Source map could not be generated.");
    } else {
        // we should have a proper source map now
        return sourceMap;
    }
}

function callback(message) {
    console.log("Message:", message.type;)
    if (message.type === "console log") {
        // the location of the console log message will be the location in the instrumented code
        /// we have to adjust it to get the position in the original code
        message.loc = getSourceMap().originalPositionFor(message.loc);
    }
    messagesToSend.push(message); // gather messages in a buffer

    // do not forward messages every time, instead gather a bunch and send them all at once
    if (messagesToSend.length > 100) {
        console.log("Sending messages.");
        process.send({type: "message batch", messages: messagesToSend});
        messagesToSend.splice(0); // empty the array
    }
}

// function to send messages when we get a chance to prevent the client from waiting too long
function sendMessagesWithEventLoopTurnaround() {
    if (messagesToSend.length > 0) {
        process.send({type: "message batch", messages: messagesToSend});
        messagesToSend.splice(0); // empty the array
    }
    setTimeout(sendMessagesWithEventLoopTurnAround, 10);
}

function executeCode(code) {
    // setup child process to calculate the source map
    importantDataCalculator = fork("./runtime");
    importantDataCalculator.on("message", function (msg) {
        if (msg.type === "result") {
            importantData = msg.data;
            console.log("Finished source map generation!")
        } else if (msg.type === "error") {
            importantData = null;
        } else {
            throw new Error("Unknown message from dataGenerator!");
        }

        if (pausedExecution) {
            // execution is waiting for the data
            pausedExecution.run();
        }
    });


    // setup automatic messages sending in the event loop
    sendMessagesWithEventLoopTurnaround();

    // instrument the code to call a function called "callback", which will be defined in the sandbox
    instrumentCode(code);

    // prepare the sandbox
    var sandbox = Contextify(new utils.Sandbox(callback)); // the callback to be called from the instrumented code is defined in the sandbox

    // wrap the execution of the code in a Fiber, so it can be paused
    Fiber(function () {
        sandbox.run(code);
        // send messages because the execution finished
        console.log("Sending messages.");
        process.send({type: "message batch", messages: messagesToSend});
        messagesToSend.splice(0); // empty the array
    }).run();
}

process.on("message", function (msg) {
    if (msg.type === "code") {
        executeCode(msg.code, msg.options);
    }
});

So to summarize: When new code is received a new process is created to execute it. This process first instruments and then executes it. Before doing so it starts a third process to calculate a source map for the code. The instrumented code calls the function named callback in the code above handing messages to the runtime that report progress of the executing code. These have to be adjusted sometimes, one example for which an adjustment is necessary are "console log" messages. To do this adjustment, the source map calculated by the third process is necessary. When the callback needs the source map it calls getSourceMap() which waits for the sourceMap process to finish its calculation and yields control to the event loop during that waiting time to enable itself to receive messages from the sourceMap process (otherwise the event loop would be blocked and no message could be received).

Messages passed to the callback are first stored in an array and then sent as a batch to the main process for performance reasons. However, we do not want the main process to wait too long for messages so in addition to sending a batch of messages when the threshold is reached we scheduled a function sendMessagesWithEventLoopTurnAround() to run in the event loop and check whether there are messages to send. This has two advantages:

1. When the execution process is waiting for the source map process it can use the time to send the messages it already got. So if the sourceMap process takes several seconds to finish, the main process does not have to wait the same time for messages that have already been created and contain correct data.
2. When the executing code generates only very little messages in the event loop (e.g. by a function scheduled with setTimeInterval(f, 2000) which only creates one single message per execution) it does not have to wait a long time until the message buffer is full (in this example 200s) but receives updates about the progress every 10ms (if anything changed).

The Problem

What works

This setup works fine in the following cases

1. I do not use fibers and a separate process to calculate the source map. Instead I calculate the source map before the code is executed. In that case all the code to execute I tried works as expected.
2. I do use fibers and a separate process and execute code for which I do not need the source map. E.g. var a = 2;
   or
   setTimeout(function () { var a = 2;}, 10)

In the first case the output looks like this.

Starting source map generation.
Message: 'variables init'
Message: 'program finished'
Sending messages.
Finished source map generation.
Source map generator process exited with code: 0 after receiving signal: null

3. I do use fibers and a separate process and code for which I need the source map but that doesn't use the event loop, e.g. console.log("foo");

In that case the output looks like this:

Starting source map generation.
Message: 'console log'
Waiting for source map generation.
Finished source map generation.
Wait is over.
Message:  'program finished'
Sending messages.
Source map generator process exited with code: 0 after receiving signal: null

4. I do use fibers and a separate process and code for which I need the source map and which uses the event loop, but the source map is only needed when the source map calculation is already finished (so no waiting).

E.g.

setTimeout(function () {
    console.log("foo!");
}, 100); // the source map generation takes around 100ms

In that case the output looks like this:

Starting source map generation.
Message: 'function declaration'
Message: 'program finished'
Sending messages.
Finished source map generation.
Source map generator process exited with code: 0 after receiving signal: null
Message: 'function enter'
Message: 'console log'
Message: 'function exit'
Sending messages in event loop.

What doesn't work

It only breaks if I use fibers and separate processes and code that uses the event loop but needs the source map before it is finished, e.g.

setTimeout(function () {
    console.log("foo!");
}, 10); // the source map generation takes around 100ms

The output then looks like this:

Starting source map generation.
Message: 'function declaration'
Message: 'program finished'
Sending messages.
Message: 'function enter'
Message: 'console log'
Waiting for source map generation.

/path/to/code/runtime.js:113
            Fiber.yield();
                       ^
getSourceMap (/path/to/code/runtime.js:113:28),callback (/path/to/code/runtime.js:183:9),/path/to/code/utils.js:102:9,Object.console.log (/path/to/code/utils.js:190:13),null._onTimeout (<anonymous>:56:21),Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
Child process exited with code: 8 after receiving signal: null

The process that crashes here is the execution process. However, I can't find out why that happens or how to track down the problem. As you can see above, I already added several log statements to find out what is happening. I am also listening to the "uncaught exception" event on the execution process, but that does not seem to be fired.

Also, the log message we see in the end is not one of mine, since I prefix my log messages with some kind of description string, so it's one created by node.js itself. I neither understand why this occurs, nor what exit code 8 or even what else I could do to narrow down the cause. Any help would be greatly appreciated.

Answer 1

As usual, once one finishes describing the problem completely a solution presents itself.

The problem, I think, is that code executed by setTimeout is not wrapped in a Fiber. So calling Fiber.yield() inside that code crashes, understandably.

Therefore, the solution is to overwrite setTimeout in the executed code. Since I am already providing a sandbox with some special functions (e.g. my own console object) I can also exchange the implementation of setTimeout by one that wraps the executed function in a fiber, like so:

// this being the sandbox object, which si the global object for the executing code
this.setTimeout = function (functionToExecute, delay) {
    return setTimeout(function () {
        fibers(functionToExecute).run();
    }, delay);
};

This implementation does not support passing additional parameters to setTimeout but it could trivially be expanded to do so. It also does not support the version of setTimeout that is passed a string of code instead of a function, but who would use that anyway?

To make it work completely I would have to exchange the implementations of setTimeout, setInterval, setImmediate and process.nextTick. Anything else that is usually used to fulfill such a role?

This only leaves the question whether there is an easier way to do this than reimplementing each of these functions?