node.jsで使える非同期コントロールフローライブラリ nue 0.6.0 リリース

0.6.0をリリースしました。npm install nue でインストールできます。

https://github.com/nakamura-to/nue

CHANGELOG

新機能 - デバッグをサポートしました。`NODE_DEBUG=nue` が使えます。
変更 - NueAsyncError を改善しました。NueAsyncError は通常のErrorオブジェクトになりました。
変更 - `nue.as` 関数の引数が必須になりました。
変更 - `history` プロパティをstepのコンテキストオブジェクトから削除しました。.
変更 - `this.asyncEach` の結果を平坦化しないようにしました.
変更 - `nue.parallel` の結果を平坦化しないようにしました.

大きなポイントは、「デバッグのサポート（デバッグログ出力）」と「非同期呼び出し時に発生したエラーに含める情報の改善」の２点です。どちら機能についても、id:koichik さんのnode-flowless v0.0.2 リリースのエントリを参考にさせてもらいました。

デバッグログ出力

ファイルを連結して出力するflow.jsで試してます。

var flow = require('nue').flow;
var as = require('nue').as;
var fs = require('fs');

var myFlow = flow('myFlow')(
  function readFiles(file1, file2) {
    fs.readFile(file1, 'utf8', this.async(as(1)));
    fs.readFile(file2, 'utf8', this.async(as(1)));
  },
  function concat(data1, data2) {
    this.next(data1 + data2);
  },
  function end(data) {
    if (this.err) throw this.err;
    console.log(data);
    console.log('done');
    this.next();
  }
);

myFlow('file1', 'file2');

デバッグ出力を有効にするには、NODE_DEBUG=nue とします。出力結果はこうなります。

$ NODE_DEBUG=nue node flow.js
NUE: begin TOP_LEVEL_FLOW. flow: myFlow(0), calledAt: /private/tmp/flow.js:21:1, args: [ 'file1', 'file2' ]
NUE: begin STEP. flow: myFlow(0), step: readFiles(0), args: [ 'file1', 'file2' ]
NUE: begin STEP. flow: myFlow(0), step: concat(1), args: [ 'FILE1', 'FILE1' ]
NUE: begin STEP. flow: myFlow(0), step: end(2), args: [ 'FILE1FILE1' ]
FILE1FILE1
done

デバッグログが出力する内容は大きく3つあります。

トップレベルのflowの開始
stepの開始
stepのエラー

flowとstepの開始時には、名前、ID、引数などを出力します。トップレベルのflowの開始時には、そのflowがどこから呼び出されたかのソースコードのパス、行番号、列番号も合わせて出力します。stepが失敗した場合は、エラーの内容を出力します。

なんで「開始」があるのに「終了」のログがないんだ？と思うかもしれません。出力することはもちろん可能なんですが、nueの場合、非常に直感に反する出力がされるんですよね。前のstepの終了と次のstepの開始が直列しないからです。どういうことかというと、nueでは前のstepがreturnしたら次のstepを始めるという仕組みではなく、前のstepでnextを呼んだら（もしくは非同期処理がすべて終わったら）次のstepが始まるのです。で、「終了」のログがあると、処理の流れが読みにくいんですよね。そういうわけで「終了」のログは出力しないことにしました。「エラー」のログがなければ正常に終了したとみなしてもらえれば。

それから、トップレベルのflowについてはソースコードのパス、行番号、列番号を出力するなら、stepについても同じようにすれば？と思うかもしれません。そうしたいのはやまやまなんですが、これができないんですよねー。パス、行番号、列番号の出力は、スタックトレースの情報を使っています。flowはアプリから呼び出されるので呼び出し元を特定できるんですが、stepを呼び出しているのはアプリじゃなくてnueだからです。stepの関数を定義された場所がスタックに登場しないのです。

非同期呼び出しで発生するエラー

上の例で使ったflow.jsですが、一番最後のmyFlowの呼び出しで第2引数を'non-existent-file'と存在しないファイル名にして実行してみます。実行結果は以下の通りです。

$ node flow.js

/private/tmp/node_modules/nue/lib/nue.js:82
          throw e;
                ^
NueAsyncError: An error occurred in an async call.
cause stack is ...
  Error: ENOENT, no such file or directory 'non-existent-file'
async call history is ...
 [ { function: 'readFiles',
    location: '/private/tmp/flow.js:8:37',
    mapping: { index: 1 } } ]
    at makeAsyncError (/private/tmp/node_modules/nue/lib/nue.js:395:13)
    at asyncCallback (/private/tmp/node_modules/nue/lib/nue.js:332:33)
    at [object Object].<anonymous> (fs.js:88:5)
    at [object Object].emit (events.js:67:17)
    at Object.oncomplete (fs.js:1059:12)

NueAsyncErrorが発生する訳ですが、「cause stack is …」の後ろにエラーとなった原因を示し、「async call history is …」の後ろで、非同期呼び出しを開始した場所（正確にはthis.asyncを呼び出した場所）やそのときの引数マッピング定義を示します。

もう少し、複雑なケースを考えてみます。非同期呼び出しがネストして、ネストした先でエラーが発生したらどうでしょう？次のコードがそうです。mainFlowの中からsubFlowを非同期実行しますが、sufFlowはfs.readFileを非同期実行します。エラーは2度目のsubFlowの呼び出しで存在しないファイル名を読もうとして発生します。

var flow = require('nue').flow;
var as = require('nue').as;
var fs = require('fs');

var subFlow = flow('subFlow')(
  function readFile(file) {
    fs.readFile(file, 'utf8', this.async(as(1)));
  }
);

var mainFlow = flow('mainFlow')(
  function start() {
    this.exec(subFlow, 'file1', this.async(as(1)));
    this.exec(subFlow, 'non-existent-file', this.async(as(1)));
  },
  function end(data1, data2) {
    if (this.err) throw this.err;
    console.log(data1 + data2);
    console.log('done');
    this.next();
  }
);

mainFlow();

実行結果です。

$ node nestingWithExec.js 

/private/tmp/node_modules/nue/lib/nue.js:82
          throw e;
                ^
NueAsyncError: An error occurred in an async call.
cause stack is ...
  Error: ENOENT, no such file or directory 'non-existent-file'
async call history is ...
 [ { function: 'readFile',
    location: '/private/tmp/nestingWithExec.js:7:36',
    mapping: { index: 1 } },
  { function: 'start',
    location: '/private/tmp/nestingWithExec.js:14:50',
    mapping: { index: 1 } } ]
    at makeAsyncError (/private/tmp/node_modules/nue/lib/nue.js:395:13)
    at asyncCallback (/private/tmp/node_modules/nue/lib/nue.js:332:33)
    at StepContext.end (/private/tmp/node_modules/nue/lib/nue.js:296:14)
    at runStep (/private/tmp/node_modules/nue/lib/nue.js:113:14)
    at lastStep (/private/tmp/node_modules/nue/lib/nue.js:79:11)
    at StepContext.endWith (/private/tmp/node_modules/nue/lib/nue.js:239:14)
    at exit (/private/tmp/node_modules/nue/lib/nue.js:98:34)
    at StepContext.endWith (/private/tmp/node_modules/nue/lib/nue.js:239:14)
    at native
    at asyncCallback (/private/tmp/node_modules/nue/lib/nue.js:332:22)

ポイントは「async call history is …」の後ろに続く、2つの非同期呼び出しの履歴です。これは、nestingWithExec.jsの14行50列で非同期呼び出しが行われ、さらにnestingWithExec.jsの7行36列でも非同期呼び出しが行われたことを示します。先頭の履歴がエラーの発生の原因となった非同期呼び出しです。ソースコードの実際と合っていますね！というわけで、非同期呼び出しがネストしていても呼び出された経路と原因がわかります。

今、ふと思いましたが、デバッグログ出力と同様、トップレベルのflowの呼び出し元の情報があるとよりわかりやすかも？

今回は、コード削減も目指していたんですが、結果的に前回リリースより約50行の削減達成。404行となりました。