process.nextTick(check) in next.group could cause a bug of race condition

[seanjsong]

I really like the way step works, simplifying my code greatly. However when I read the code of step, I'm really skeptical about this:

function check() {
  if (pending === 0) {
    // When group is done, call the callback
    localCallback(error, result);
  }
}
process.nextTick(check2); // Ensures that check is called at least once

I believe the comment "Ensures that check is called at least once" actually means:

If var group = this.group() is executed but no subsequent group() is called, we have to make sure the next step is called back anyway (with result equal to []).

That's right. But what if there are subsequent group() calls? If this next-tick-check is done before any asynchronous callbacks (returned by subsequent group() calls) are called, it's harmless, because pending can't be equal to 0. However, if the next-tick-check is called last, it could be disastrous because localCallback will consume another step function with the same result.

The thing is, you can't assume process.nextTick callback will be called in the very first place. This thread talks about it: https://groups.google.com/forum/?fromgroups=#!topic/nodejs/e8nLG5xrorA . From time to time process.nextTick callback really happens as the last one.

I have managed to construct a counter-example. Firstly, to facilitate watching, I changed step.js a little:

function check() {
  console.trace('check by callback');
  if (pending === 0) {
    console.trace('do by callback');
    // When group is done, call the callback
    localCallback(error, result);
  }
}
function check2() {
  console.trace('check by nextTick');
  if (pending === 0) {
    console.trace('do by nextTick');
    // When group is done, call the callback
    localCallback(error, result);
  }
}
process.nextTick(check2); // Ensures that check is called at least once

Then I run this test code:

var fs = require('fs'),
    path = require('path'),
    step = require('step');

var root = path.join(__dirname, 'test'),
    files;

step(
  function () {
    fs.readdir(root, this);
  },
  function (err, _files) {
    if (err) { throw err; return; }
    files = _files;
    var group = this.group();
    files.forEach(function (file) { fs.stat(path.join(root, file), group()); });
  },
  function (err, stats) {
    if (err) { throw err; return; }
    var group = this.group();
    files.filter(function (file, i) {
      return stats[i].isFile();
    }).forEach(function (file) { fs.readFile(path.join(__dirname, 'test', file), group()); });
  },
  function (err, contents) {
    if (err) { throw err; return; }
    console.log(contents);
  }
);

When there are only one file and one directory under test directory, I get the result, unfortunately, like this:

$ node test.js 
Trace: check by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:98:15)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at Object.oncomplete (fs.js:297:15)
Trace: check by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:98:15)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at Object.oncomplete (fs.js:297:15)
Trace: do by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:100:17)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at Object.oncomplete (fs.js:297:15)
Trace: check by nextTick
    at check2 (/home/djkings/mdblog/node_modules/step/lib/step.js:106:15)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)
Trace: do by nextTick
    at check2 (/home/djkings/mdblog/node_modules/step/lib/step.js:108:17)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)
[ { dev: 2051,
    ino: 4335031,
    mode: 33188,
    nlink: 1,
    uid: 1000,
    gid: 1000,
    rdev: 0,
    size: 1557,
    blksize: 4096,
    blocks: 8,
    atime: Tue Oct 16 2012 11:09:49 GMT+1300 (NZDT),
    mtime: Tue Oct 16 2012 10:49:08 GMT+1300 (NZDT),
    ctime: Tue Oct 16 2012 10:49:08 GMT+1300 (NZDT) },
  { dev: 2051,
    ino: 4335032,
    mode: 16893,
    nlink: 2,
    uid: 1000,
    gid: 1000,
    rdev: 0,
    size: 4096,
    blksize: 4096,
    blocks: 8,
    atime: Mon Oct 15 2012 17:48:52 GMT+1300 (NZDT),
    mtime: Sun Oct 14 2012 09:46:50 GMT+1300 (NZDT),
    ctime: Tue Oct 16 2012 10:49:16 GMT+1300 (NZDT) } ]
Trace: check by nextTick
    at check2 (/home/djkings/mdblog/node_modules/step/lib/step.js:106:15)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)
Trace: check by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:98:15)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at fs.readFile (fs.js:176:14)
    at Object.oncomplete (fs.js:297:15)
Trace: do by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:100:17)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at fs.readFile (fs.js:176:14)
    at Object.oncomplete (fs.js:297:15)

However, when I add one more file to the test directory, the timing changes accordingly:

$ node test.js 
Trace: check by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:98:15)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at Object.oncomplete (fs.js:297:15)
Trace: check by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:98:15)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at Object.oncomplete (fs.js:297:15)
Trace: check by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:98:15)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at Object.oncomplete (fs.js:297:15)
Trace: do by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:100:17)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at Object.oncomplete (fs.js:297:15)
Trace: check by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:98:15)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at fs.readFile (fs.js:176:14)
    at Object.oncomplete (fs.js:297:15)
Trace: check by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:98:15)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at fs.readFile (fs.js:176:14)
    at Object.oncomplete (fs.js:297:15)
Trace: do by callback
    at check (/home/djkings/mdblog/node_modules/step/lib/step.js:100:17)
    at next.group (/home/djkings/mdblog/node_modules/step/lib/step.js:127:22)
    at fs.readFile (fs.js:176:14)
    at Object.oncomplete (fs.js:297:15)
[ <Buffer 23 20 56 6f 64 6b 61 0a 0a 23 23 20 4e 65 6d 69 72 6f 66 66 20 44 65 6c 69 6b 61 74 0a 0a 21 5b 4e 65 6d 69 72 6f 66 66 20 44 65 6c 69 6b 61 74 5d 28 76 ...>,
  <Buffer 23 20 47 69 6e 0a 0a 2e 2e 2e 74 68 65 20 62 65 73 74 20 64 72 69 6e 6b 20 69 6e 20 65 78 69 73 74 65 6e 63 65 20 69 73 20 74 68 65 20 50 61 6e 20 47 61 ...> ]
Trace: check by nextTick
    at check2 (/home/djkings/mdblog/node_modules/step/lib/step.js:106:15)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)
Trace: do by nextTick
    at check2 (/home/djkings/mdblog/node_modules/step/lib/step.js:108:17)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)
Trace: check by nextTick
    at check2 (/home/djkings/mdblog/node_modules/step/lib/step.js:106:15)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)
Trace: do by nextTick
    at check2 (/home/djkings/mdblog/node_modules/step/lib/step.js:108:17)
    at process.startup.processNextTick.process._tickCallback (node.js:244:9)

I guess now you know what I mean. Ideally we should handle the empty group case just like handling the empty parallel case, checking it synchronously rather than by process.nextTick. As an exercise I'll try to fix this problem but it might involve major revision in step.js.

[bminer]

Yeah... I noticed this bug in the past, as well. The way I normally do this (and the way I handled it in my async lib ) is by keeping track of the total number of callbacks and the completed number of callbacks. That way, totalCallbacks is incremented asynchronously and you don't get strange behavior. Once completedCallbacks >= totalCallbacks, you know that you are done.