Node.js の Async Hooks API の動作を検証しました


必要に迫られて、Node.js の [Async Hooks] API について調べたので、その仕組を実例を用いて説明します。

## Async Hooks とは?

Node.js の [Stability: 1 - Experimental](https://nodejs.org/dist/latest-v12.x/docs/api/documentation.html#documentation_stability_index) (2019/12/30 現在) な機能です。
主に **非同期呼出を追跡する** のに使われています。例えば以下の様な NPM Module が [Async Hooks] を使っています。

* [trace](https://github.com/AndreasMadsen/trace) → 非同期呼出で途切れる Stack trace を繋げて表示する
* [express-http-context](https://github.com/skonves/express-http-context) → リクエスト毎に異なるコンテキストに値を保存/取得する express middleware  

## 対象読者

事前に [Node.jsでのイベントループの仕組みとタイマーについて] について知っておくことをオススメします。

## 動作環境

本記事は以下の環境で試しています。

* Mac OS 10.13.6
* Node.js v12.13.0

私は [nodebrew] を使っています。

```
nodebrew binary-install v12.13.0
nodebrew use v12.13.0
```

## コード

記事で書くコードそのものが↓です。

* https://github.com/megmogmog1965/asynchooks-examples

## [Async Hooks] の概要

公式の [Node.js >> Async Hooks >> Overview] の通りですが、実際に動かして見ないとドキュメントだけ読んでも分かりづらいです。まずはざっくり概要です。

[Async Hooks] 自体は、以下の様に ``async_hooks.createHook()`` するだけで使えます。

```javascript
const async_hooks = require('async_hooks');

// 現在 (↓が実行されてる瞬間) の Async ID を取得できます。
const eid = async_hooks.executionAsyncId();

// Async Hook を生成します。
// ここで渡した４つの callback functions が、非同期呼び出しの際に呼ばれる様になります。
const asyncHook = async_hooks.createHook({
  init,
  before,
  after,
  destroy,
});

// 有効にしないと callback functions が呼ばれません。
asyncHook.enable();
```

前述の ``async_hooks.createHook()`` に渡した４つの callback functions は自由に実装できます。
今回は、確認の為に、呼出の際の引数値を ``Array`` に保存しておく様にしました。

```javascript
// [init] setTimeout() 等の非同期処理 (callback function) の登録をした時に呼ばれます。
function init(asyncId, type, triggerAsyncId, resource) {
  // Promise による callback task 登録の場合、Promise オブジェクト自身が来るので、
  // ちゃんと GC されるように参照保持しないようにします。
  arguments[3] = resource.constructor.name === 'PromiseWrap' ? resource.toString() : resource;

  historyInit.push(arguments);
}

// [before] 登録した callback function が実行される「直前」に呼ばれます。
function before(asyncId) {
  historyBefore.push(asyncId);
}

// [after] 登録した callback function が実行された「後」に呼ばれます。
function after(asyncId) {
  historyAfter.push(asyncId);
}

// [destroy] 非同期リソースが破棄 (≒登録した非同期処理の完了) された時に呼ばれます。
function destroy(asyncId) {
  historyDestroy.push(asyncId);
}

// Async Hooks の動作確認の為に、init, before, after, destroy 呼出の際の引数値をここ↓に保存しておきます。
const historyInit = [];
const historyBefore = [];
const historyAfter = [];
const historyDestroy = [];
```

この状態で ``setTimeout()`` 等を実行すると、 [init], [before], [after], [destroy] callback functions が順に呼ばれるようになります。

## init, before, after, destroy の定義

### 時系列

API ``setInterval`` での例です。

![setInterval.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/60131/3bcbda3d-6510-bf52-2345-f8a4673230a5.png "setInterval.png")

### [init]

非同期 API (``setTimeout``, ``Promise`` 等) を実行した瞬間に呼ばれます。

> 別の言い方をすると、非同期処理 (callback functions) が event queue に登録された時です。

* １度だけ **必ず** 呼ばれます

|引数名|型|説明|
|:--|:--|:--|
|asyncId |Number |分岐元 (親) の Async ID |
|[type] |String |``Timeout``, ``PROMISE`` 等の識別子が来ます。[resource] の名称です。 |
|[triggerAsyncId] | Number |分岐元 (親) の Async ID |
|[resource] |Object |実行した非同期処理の情報。``Promise`` の場合、promise object 自身が来るので、参照保持で GC を阻害しないように注意。 |

### [before]

登録した callback function が実行される **直前** に呼ばれます。

* **一度も呼ばれない事があります** 例えば ``net.createServer`` で Socket listen していても、接続がなければ callback 実行されません
* ``setInterval`` 等、一度の callback 登録で [before] は **複数回** 呼ばれる事があります

|引数名|型|説明|
|:--|:--|:--|
|asyncId |Number |分岐元 (親) の Async ID |

### [after]

登録した callback function が実行された **後** に呼ばれます。

* [before] と同様に、 **一度も呼ばれない** もしくは **複数回** 呼ばれる事があります
* callback で例外が発生し catch されなかった場合、 ``uncaughtException`` event もしくは handler 実行の後に、[after] が呼ばれます

|引数名|型|説明|
|:--|:--|:--|
|asyncId |Number |分岐元 (親) の Async ID |

### [destroy]

非同期リソース [resource]　が **破棄** (≒登録した非同期処理の完了) された時に **一度だけ** 呼ばれます。

> 具体的にいつ呼ばれるかはまちまちで、例えば ``Promise`` の場合は promise object が GC により破棄された際に呼ばれます

|引数名|型|説明|
|:--|:--|:--|
|asyncId |Number |分岐元 (親) の Async ID |

## Examples

ドキュメントを読んだだけでは、[init], [before], [after], [destroy] callback functions がそれぞれ、どのタイミングで、何回呼ばれるのか、よく分かりません。

実際に実行して試してみます。

### 下準備

前述のコードをファイル名 ``register-hook.js`` とし、以下の Debug Print 関数を ``module.exports`` します。

> わざと ``setTimeout`` で表示処理を非同期実行してます。

```javascript:register-hook.js
const async_hooks = require('async_hooks');

const asyncHook = async_hooks.createHook({ init, before, after, destroy });
asyncHook.enable();

// ...
// 省略...
// ...

/**
 * async_hooks で取得した非同期呼び出しの履歴を表示します.
 */
module.exports = function () {
  // 表示処理が呼出元とは異なる event task として実行される様、setTimeout する. (event queue に入れておく)
  setTimeout(function printHistory() {
    const [init, before, after, destroy]
      = [[...historyInit], [...historyBefore], [...historyAfter], [...historyDestroy]];

    console.log('FirstExecutionAsyncId: ', eid, '\n');
    console.log('async_hook calls: init: ', init, '\n');
    console.log('async_hook calls: before: ', before, '\n');
    console.log('async_hook calls: after: ', after, '\n');
    console.log('async_hook calls: destroy: ', destroy, '\n');
  }, 10);
}
```

### (1) setTimeout で Async Hooks

![example-setTimeout.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/60131/13c65bd7-0fdd-2618-3928-a5cff2457b39.png "example-setTimeout.png")

まずは [Async Hooks] を有効にした状態で ``setTimeout`` を呼ぶとどうなるか見てみます。

```javascript:index_setTimeout.js
const printHistory = require('./register-hook');

function _01_SetTimeoutCallbackFunction() {
  printHistory(); // ← setTimeout 経由で console.log する.
}

setTimeout(_01_SetTimeoutCallbackFunction);
```

以下の様に ``printHistory()`` で出力されます。

```
FirstExecutionAsyncId:  1 

async_hook calls: init:  [
  [Arguments] {
    '0': 2,
    '1': 'Timeout',
    '2': 1,
    '3': Timeout {
      _idleTimeout: 1,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 44,
      _onTimeout: [Function: _01_SetTimeoutCallbackFunction],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: true,
      [Symbol(refed)]: null,
      [Symbol(asyncId)]: 2,
      [Symbol(triggerId)]: 1
    }
  },
  [Arguments] {
    '0': 3,
    '1': 'Timeout',
    '2': 2,
    '3': Timeout {
      _idleTimeout: 10,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 46,
      _onTimeout: [Function: printHistory],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: true,
      [Symbol(asyncId)]: 3,
      [Symbol(triggerId)]: 2
    }
  }
] 

async_hook calls: before:  [ 2, 3 ] 

async_hook calls: after:  [ 2 ] 

async_hook calls: destroy:  [ 2 ] 
```

> エントリファイルの ``index_setTimeout.js`` が実行された直後の Async ID は ``1`` です

#### [init] は２回呼ばれています。

１回目は ``setTimeout(_01_SetTimeoutCallbackFunction)`` (id=``2``) で、 ``index_setTimeout.js`` ファイル自身 (id=``1``) からトリガーされた非同期タスクである事が分かります。

２回目は ``setTimeout(printHistory)`` (id=``3``) で、先程の ``setTimeout(_01_SetTimeoutCallbackFunction)`` (id=``2``) からトリガーされた非同期タスクである事が分かります。

#### [before] は２回呼ばれています。

function ``_01_SetTimeoutCallbackFunction`` (id=``2``) と ``printHistory`` (id=``3``) が呼出されたからです

#### [after] は１回呼ばれています。

function ``_01_SetTimeoutCallbackFunction`` (id=``2``) の実行は完了したが、 ``printHistory`` (id=``3``) はまだ途中だからです

#### [destroy] は１回呼ばれています。

function ``_01_SetTimeoutCallbackFunction`` (id=``2``) の破棄は完了したが、 ``printHistory`` (id=``3``) はまだ実行途中で破棄されてないからです

### (2) setInterval で Async Hooks

![example-setInterval.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/60131/fcf93dd9-969a-2bfe-7fd8-6dce3f7c712c.png "example-setInterval.png")

次に [Async Hooks] を有効にした状態で ``setInterval`` を呼ぶとどうなるか見てみます。

```javascript:index_setInterval.js
const printHistory = require('./register-hook');

let count = 0;

function _01_SetIntervalCallbackFunction() {
  if (++count > 10) {
    clearInterval(intervalID);
    printHistory(); // ← setTimeout 経由で console.log する.
  }
}

const intervalID = setInterval(_01_SetIntervalCallbackFunction, 10);
```

以下の様に ``printHistory()`` で出力されます。

```
FirstExecutionAsyncId:  1 

async_hook calls: init:  [
  [Arguments] {
    '0': 2,
    '1': 'Timeout',
    '2': 1,
    '3': Timeout {
      _idleTimeout: -1,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 157,
      _onTimeout: null,
      _timerArgs: undefined,
      _repeat: 10,
      _destroyed: true,
      [Symbol(refed)]: null,
      [Symbol(asyncId)]: 2,
      [Symbol(triggerId)]: 1
    }
  },
  [Arguments] {
    '0': 3,
    '1': 'Timeout',
    '2': 2,
    '3': Timeout {
      _idleTimeout: 10,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 171,
      _onTimeout: [Function: printHistory],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: true,
      [Symbol(asyncId)]: 3,
      [Symbol(triggerId)]: 2
    }
  }
] 

async_hook calls: before:  [
  2, 2, 2, 2, 2,
  2, 2, 2, 2, 2,
  2, 3
] 

async_hook calls: after:  [
  2, 2, 2, 2, 2,
  2, 2, 2, 2, 2,
  2
] 

async_hook calls: destroy:  [ 2 ]
```

#### [init] は２回呼ばれています。

１回目は ``setInterval(_01_SetIntervalCallbackFunction, 10)`` (id=``2``) で、 ``index_setInterval.js`` ファイル自身 (id=``1``) からトリガーされた非同期タスクである事が分かります。

２回目は ``setTimeout(printHistory)`` (id=``3``) で、先程の ``setTimeout(_01_SetIntervalCallbackFunction)`` (id=``2``) からトリガーされた非同期タスクである事が分かります。

#### [before] は１１回呼ばれています。

このコードでは、１度の ``setInterval(_01_SetIntervalCallbackFunction, 10)`` で callback function ``_01_SetIntervalCallbackFunction`` (id=``2``) は 10 ms おきに実行され、``clearInterval()`` されるまで **計１０回** 呼ばれています。

また、 ``printHistory`` (id=``3``) も１度呼出され、カウントされます。

#### [after] は１０回呼ばれています。

[before] で述べた通り、``_01_SetIntervalCallbackFunction`` (id=``2``) は **計１０回** 実行されました。

``printHistory`` (id=``3``) の処理はまだ途中の為、カウントされません。

#### [destroy] は１回呼ばれています。

``clearInterval`` の実行により callback function ``_01_SetTimeoutCallbackFunction`` (id=``2``) は破棄されます。

``printHistory`` (id=``3``) はまだ実行途中で破棄されてないので、カウントされません。


### (3) Promise で Async Hooks

![example-promise.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/60131/6f369f08-5e75-7811-f574-6ce0cc45ba20.png "example-promise.png")

最後に [Async Hooks] を有効にした状態で ``new Promise(callback)`` を呼ぶとどうなるか見てみます。

```javascript:index_promise.js
const printHistory = require('./register-hook');

function _01_PromiseCallbackFunction (resolve, _) {
  resolve();
}

function _02_PromiseThenCallbackFunction (_) {
  // GC で Promise オブジェクトを破棄しないと "async_hooks.destroy" callback は呼ばれない.
  setTimeout(global.gc);

  printHistory(); // ← setTimeout 経由で console.log する.
}

new Promise(_01_PromiseCallbackFunction)
  .then(_02_PromiseThenCallbackFunction);
```

以下の様に ``printHistory()`` で出力されます。

```
FirstExecutionAsyncId:  1 

async_hook calls: init:  [
  [Arguments] {
    '0': 2,
    '1': 'PROMISE',
    '2': 1,
    '3': '[object PromiseWrap]'
  },
  [Arguments] {
    '0': 3,
    '1': 'PROMISE',
    '2': 2,
    '3': '[object PromiseWrap]'
  },
  [Arguments] {
    '0': 4,
    '1': 'Timeout',
    '2': 3,
    '3': Timeout {
      _idleTimeout: 1,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 49,
      _onTimeout: [Function: gc],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: true,
      [Symbol(refed)]: null,
      [Symbol(asyncId)]: 4,
      [Symbol(triggerId)]: 3
    }
  },
  [Arguments] {
    '0': 5,
    '1': 'Timeout',
    '2': 3,
    '3': Timeout {
      _idleTimeout: 10,
      _idlePrev: null,
      _idleNext: null,
      _idleStart: 49,
      _onTimeout: [Function: printHistory],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: true,
      [Symbol(asyncId)]: 5,
      [Symbol(triggerId)]: 3
    }
  }
] 

async_hook calls: before:  [ 3, 4, 5 ] 

async_hook calls: after:  [ 3, 4 ] 

async_hook calls: destroy:  [ 2, 3, 4 ]
```

> ちょっとごちゃごちゃしているのは、``new Promise(callback)`` に加え、
> ``Promise.then()`` の呼出と、``setTimeout(global.gc)`` の呼出があるからです。

#### [init] は４回呼ばれています。

１回目は ``new Promise(_01_PromiseCallbackFunction)`` (id=``2``) で、 ``index_promise.js`` ファイル自身 (id=``1``) からトリガーされた非同期タスクである事が分かります。

２回目は ``promise.then(_02_PromiseThenCallbackFunction)`` (id=``3``) で、 ``new Promise(_01_PromiseCallbackFunction)`` (id=``2``) からトリガーされた非同期タスクである事が分かります。

３回目は意図的にコード ``setTimeout(global.gc)`` を記述した為に、記録されています。

> [destroy] で後述しますが、 ``Promise`` の場合は GC で promise object 破棄されるまで [destroy] が呼出されません

４回目は ``setTimeout(printHistory)`` (id=``5``) で、先程の ``promise.then(_02_PromiseThenCallbackFunction)`` (id=``3``) からトリガーされた非同期タスクである事が分かります。

#### [before] は３回呼ばれています。

正直意図しない動きをしています。

* ``new Promise(_01_PromiseCallbackFunction)`` (id=``2``) では [before] は **呼出されない**
* ``promise.then(_02_PromiseThenCallbackFunction)`` (id=``3``) では [before] は **呼出される**

以下の通り、公式のドキュメントにもそれとなく書いてありますが、どうしてこういう動作になるのか理解できていません。

* [promiseResolve(asyncId)]
* [async hooks promise not destroyed]

#### [after] は２回呼ばれています。

[before] と同様です。

> ``printHistory`` (id=``5``) の処理はまだ途中の為、カウントされません。

#### [destroy] は３回呼ばれています。

``Promise`` の場合、promise object が **破棄 (=GC)** されるまで [destroy] は呼出されません。

本コードでは、意図的に ``global.gc()`` を実行しました。

> ``printHistory`` (id=``5``) はまだ実行途中で破棄されてないので、カウントされません。


[Node.js]:https://nodejs.org/ja/
[nodebrew]:https://github.com/hokaccha/nodebrew
[Async Hooks]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html

[Node.jsでのイベントループの仕組みとタイマーについて]:https://blog.hiroppy.me/entry/nodejs-event-loop

[Node.js >> Async Hooks >> Overview]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_overview

[init]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_init_asyncid_type_triggerasyncid_resource
[before]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_before_asyncid
[after]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_after_asyncid
[destroy]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_destroy_asyncid

[type]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_type
[triggerAsyncId]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_triggerasyncid
[resource]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_resource

[async hooks promise not destroyed]:https://github.com/nodejs/node/issues/14446
[promiseResolve(asyncId)]:https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_promiseresolve_asyncid