hapi の req.info.responded が 0 になる
◆ Node.js 14 では Date.now() のタイムスタンプが入るけど
◆ Node.js 12 だと 0 になってた
◆ Node.js の req, res のイベント発火順が 12 と 14 で違ってる
◆ Node.js 12 だと 0 になってた
◆ Node.js の req, res のイベント発火順が 12 と 14 で違ってる
hapi で response を返した時刻をログしようと req.info.responded を使ってました
このプロパティはレスポンスを返した時刻のミリ秒が入っています
ですが 別の環境で実行するとずっと 0 になっていました
ドキュメントによれば まだレスポンスを返してないかレスポンスエラーの場合に 0 になるとあります
しかし 特にエラーはないレスポンスでも どのリクエストも 0 です
0 になる環境では複雑にいろいろプラグインを入れたり request イベントをリッスンしているのが hapi 以外にもあったりするのでそのへんが影響してるのかもしれません
inert の静的ファイルや vision のテンプレートエンジンの処理があるとレスポンスを返すのが遅延したりするのかもです
と思ってましたが ただの JSON を返すだけのルートでも 0 でした
気になったのでどんどん機能を削除していったら ほぼ初期状態になったのにまだ 0 でした
このサーバで 「/foo/bar」 にリクエストした結果がこれです
hapi やその依存モジュールのバージョン違いかと思いましたがこれも一緒でした
念の為 node_modules ごと全部をコピーして実行しても結果が異なります
環境は responded に時刻が入るのは Windows で 0 なのは Linux なので OS によるネットワーク関係の違いが影響したりしてるのでしょうか?
……そんな感じで諦めようとしたときに Linux 側は Node.js 12 のままだったことに気づきました
Windows の方は 14 です
OS の種類以上に関係ありそうです
Linux 側のバージョンを 14 にアップデートしてから再度実行してみると
取得できています
とりあえず hapi で responded がセットされるところを見てみます
https://github.com/hapijs/hapi/blob/v20.0.2/lib/transmit.js#L282
これは internals.end 関数の中身で この関数が呼び出されるのは internals.pipe 関数中でセットしたリスナからです
https://github.com/hapijs/hapi/blob/v20.0.2/lib/transmit.js#L247,L256
生の Node.js の req, res のイベントが元になっています
また responded のセット後の処理は team.attend するだけです
これは Promise を resolve していて
https://github.com/hapijs/hapi/blob/v20.0.2/lib/request.js#L456
の await で次の処理に進みます
次の this._finalize() の中で hapi の response イベントが emit されています
そうなると 順番的には responded に時刻がセットされたあとに response イベント時が呼び出されているはずです
セットされていないということは
この if 文に入れていないということです
!event を満たすのは finish イベントが close イベントより先に来た場合です
逆の場合は event に "close" が入っていて responded がセットされません
その後に finish イベントが来ても 2 回目はもっと前に早期 return されるのでここは処理されません
イベントの順番はメジャーアップデートで変わりそうですね
Node.js 12
Node.js 14
Node.js 14 では response 側が request 側より先にイベントを emit するようですね
そのせいで close と finish の順番が逆になっています
バージョンは 12, 14 ともに手元にあったいくつかのバージョンで実行しましたが どれも同じだったので変更されたのはたぶんメジャーアップデートのタイミングか 13 のどこかだと思います
一応バージョンは 12.16 と 14.15 が試したバージョンの中でそれぞれ一番新しいものです
このプロパティはレスポンスを返した時刻のミリ秒が入っています
ですが 別の環境で実行するとずっと 0 になっていました
ドキュメントによれば まだレスポンスを返してないかレスポンスエラーの場合に 0 になるとあります
request response timestamp (0 is not responded yet or response failed when completed is set).
しかし 特にエラーはないレスポンスでも どのリクエストも 0 です
0 になる環境では複雑にいろいろプラグインを入れたり request イベントをリッスンしているのが hapi 以外にもあったりするのでそのへんが影響してるのかもしれません
inert の静的ファイルや vision のテンプレートエンジンの処理があるとレスポンスを返すのが遅延したりするのかもです
と思ってましたが ただの JSON を返すだけのルートでも 0 でした
気になったのでどんどん機能を削除していったら ほぼ初期状態になったのにまだ 0 でした
const Hapi = require("@hapi/hapi")
async function main() {
const server = new Hapi.Server({ port: 8000 })
server.events.on("response", req => {
console.log(req.path, req.info.responded)
})
server.route({
method: "GET",
path: "/{p*}",
async handler() {
return { foo: "bar" }
},
})
await server.start()
console.log("server port is " + server.info.port)
}
main()
このサーバで 「/foo/bar」 にリクエストした結果がこれです
/foo/bar 0
hapi やその依存モジュールのバージョン違いかと思いましたがこれも一緒でした
念の為 node_modules ごと全部をコピーして実行しても結果が異なります
環境は responded に時刻が入るのは Windows で 0 なのは Linux なので OS によるネットワーク関係の違いが影響したりしてるのでしょうか?
……そんな感じで諦めようとしたときに Linux 側は Node.js 12 のままだったことに気づきました
Windows の方は 14 です
OS の種類以上に関係ありそうです
Linux 側のバージョンを 14 にアップデートしてから再度実行してみると
/foo/bar 1605604271497
取得できています
なぜ動きが違うの
なぜこんな違いが出るのか Node.js 14 で何が変わったのか気になりますとりあえず hapi で responded がセットされるところを見てみます
https://github.com/hapijs/hapi/blob/v20.0.2/lib/transmit.js#L282
if (request.raw.res.finished) {
if (!event) {
request.info.responded = Date.now();
}
team.attend();
return;
}
これは internals.end 関数の中身で この関数が呼び出されるのは internals.pipe 関数中でセットしたリスナからです
https://github.com/hapijs/hapi/blob/v20.0.2/lib/transmit.js#L247,L256
const aborted = internals.end.bind(null, env, 'aborted');
const close = internals.end.bind(null, env, 'close');
const end = internals.end.bind(null, env, null);
request.raw.req.on('aborted', aborted);
request.raw.req.on('close', close);
request.raw.res.on('close', close);
request.raw.res.on('error', end);
request.raw.res.on('finish', end);
生の Node.js の req, res のイベントが元になっています
また responded のセット後の処理は team.attend するだけです
これは Promise を resolve していて
https://github.com/hapijs/hapi/blob/v20.0.2/lib/request.js#L456
await Transmit.send(this);
this._finalize();
の await で次の処理に進みます
次の this._finalize() の中で hapi の response イベントが emit されています
そうなると 順番的には responded に時刻がセットされたあとに response イベント時が呼び出されているはずです
セットされていないということは
if (!event) {
request.info.responded = Date.now();
}
この if 文に入れていないということです
!event を満たすのは finish イベントが close イベントより先に来た場合です
逆の場合は event に "close" が入っていて responded がセットされません
その後に finish イベントが来ても 2 回目はもっと前に早期 return されるのでここは処理されません
イベントの順番はメジャーアップデートで変わりそうですね
Node.js 12 と 14 の違い
リッスンしているのは生の Node.js のイベントなのでこういうコードを用意しましたrequire("http")
.createServer((req, res) => {
const log = text => () => console.log(text)
req.on("close", log("req close"))
res.on("close", log("res close"))
res.on("finish", log("res finish"))
res.end("ok")
})
.listen(8000)
Node.js 12
req close
res finish
res close
Node.js 14
res finish
res close
req close
Node.js 14 では response 側が request 側より先にイベントを emit するようですね
そのせいで close と finish の順番が逆になっています
バージョンは 12, 14 ともに手元にあったいくつかのバージョンで実行しましたが どれも同じだったので変更されたのはたぶんメジャーアップデートのタイミングか 13 のどこかだと思います
一応バージョンは 12.16 と 14.15 が試したバージョンの中でそれぞれ一番新しいものです