Node.js debug trace seems to imply multiple threads of execution - how to correctly interpret this?

Question

I'm having some trouble with Node.js, and I think the problem might be that I am misunderstanding Node.js's approach to concurrency. Here is a stripped down example of the server I have written. The idea is that the server will be used for automated testing: it keeps a list of expected "configurations", and compares them to "configurations" that are sent by the client.

//expectedConfigurations gets initialized up here

var server = http.createServer(function(request, response) {
    switch (url.pathname) {
        case "/check-configuration":
            jsonData = "";
            request.on("data", function(data) {
                return jsonData += data;
            });

            request.on("end", function() {
                var configuration, errMsg, expectedConfiguration;

                console.log("finished reading json data", jsonData);
                expectedConfiguration = expectedConfigurations.shift();
                console.log("Expected configuration", expectedConfiguration);
                configuration = new Set(JSON.parse(jsonData));
                if (expectedConfiguration.equals(configuration)) {
                    response.writeHead(200, {"Content-Type": "text/plain"});
                    response.write("Matched expected configuration.");
                    return response.end();
                } else {
                    response.writeHead(500, {
                        "Content-Type": "text/plain"
                        });
                    errMsg = "Did not match expected configuration. Received: " + (JSON.stringify(configuration)) + ". Expected:" + (JSON.stringify(expectedConfiguration)) + ".";
                    response.write(errMsg);
                    response.end();
                    console.error(errMsg);
                    results.testsFailed.push(currentTest);
                    return transitionToBeforeSendingTestState();
                }

            })
    }
})

My understanding is that Node.js is single-threaded, so while it can spawn multiple tasks which can be handled asynchronously, only one thread of execution at a time will enter the JavaScript code running under Node.js. Unfortunately, the debugging output I am receiving from my server seems to defy this assumption:

received request for /check-configuration
finished reading json data [ "a" ]
Expected configuration [ "a" ]
received request for /check-configuration
Did not match expected configuration. Received: [ "a" ]. Expected: [ "c" ].

I read this as the following:

1. the server receives a request. It starts reading request data asynchronously.
2. the server finishes reading request data, mutates expectedConfigurations by shifting it, and assigns the results to expectedConfiguration [ 'a' ]
3. the thread then gets interrupted by a new request to the server! this is where my expectations of single-threaded execution of JavaScript content under Node.js seem to break down.
4. finally, the original thread of execution associated with the first request resumes. The expected configuration is compared to the received actual configuration, but now, instead of having the value [ 'a' ], as it did in step 2., it has the value ["c"].

It seems I must be interpreting this incorrectly, because it defies my understanding of Node.js's single-threaded execution model, but right now I'm unable to see how else this can be interpreted. I'd appreciate any guidance anyone can offer on this.

Answer 1

try to repeat same test using console.error instead of console.log everywhere. As far as I know, console.log is non-blocking (data is buffered at the time of call and written to stdout at some point later) and console.error is blocking.