Azure Functionsを使い始めて、慣れないNode.jsで書いている中でたまたま発見した問題について。
同期処理をしたいため、co とPromiseを組み合わせて実装していた中で、Promise内で例外処理を対応できずにrejectを呼ばずに終えてしまいました。そうすると、起動されたFunctionが終了しないまま生き続けるのです
再現方法
さっくりと再現するためのコードを書いてみました。
var co = require('co');
function doPromise() {
return new Promise(function() {
throw 'error';
});
}
module.exports = function (context, req) {
context.log('Function started.');
co(function*() {
yield doPromise();
context.log(context.bindings.res);
context.bindings.res = { body: 'Hey' };
context.done();
});
};
そして、これをAzure 上で実行するとタイムアウトになる。実行結果は以下のとおり。
2017-10-13T23:10:44 Welcome, you are now connected to log-streaming service.
2017-10-13T23:11:10.991 Function started (Id=54c412b5-7c66-4427-b5b3-e832ad0d2258)
2017-10-13T23:11:11.476 JavaScript HTTP trigger function processed a request.
2017-10-13T23:12:45 No new trace in the past 1 min(s).
2017-10-13T23:13:45 No new trace in the past 2 min(s).
2017-10-13T23:14:45 No new trace in the past 3 min(s).
2017-10-13T23:15:16.379 Function completed (Failure, Id=db08850b-d39f-4500-a150-e94416da22de, Duration=300347ms)
2017-10-13T23:15:16.495 Microsoft.Azure.WebJobs.Host: Timeout value of 00:05:00 was exceeded by function: Functions.PromiseDemo.
2017-10-13T23:16:11.718 Function completed (Failure, Id=54c412b5-7c66-4427-b5b3-e832ad0d2258, Duration=300708ms)
2017-10-13T23:16:11.900 Microsoft.Azure.WebJobs.Host: Timeout value of 00:05:00 was exceeded by function: Functions.PromiseDemo.
さらに厄介なことに、ホスティングプランをConsumption で作成したFunctionなら5分でタイムアウトになるが、App Service だと動き続けてしまう
原因
ローカルで再現させると、何が原因で止まっているのかがわかる。
func host start
[10/13/17 10:10:54 PM] Function started (Id=da82b754-0185-4d4b-80c6-61c894899c8f)
[10/13/17 10:10:54 PM] Executing 'Functions.PromiseDemo' (Reason='This function was programmatically called via the host APIs.', Id=da82b754-0185-4d4b-80c6-61c894899c8f)
info: Worker.Node.99a9e4de-8a23-4623-8ced-2771b8ffa481[0]
(node:34664) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 2): error
info: Worker.Node.99a9e4de-8a23-4623-8ced-2771b8ffa481[0]
(node:34664) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
[10/13/17 10:10:54 PM] JavaScript HTTP trigger function processed a request.
どうやらPromise内で発生した例外はそのままでは止まら無いため、プロセスはそのまま残り続けるようだ。 INFOレベルのメッセージを読む限りでは、この状態のPromiseが発生すると、Node.jsのプロセスが異常終了するようになるらしい。
対策
対策というほどでもないのだけれど、ちゃんとtry { ... } catch() { ... }
で捉えて、reject
を実行しましょう、ということ。
先の例を書き直すと、以下のような感じに。
var co = require('co');
function doPromise() {
return new Promise(function(resolve, reject) {
try {
throw 'error';
} catch(err) {
reject(err);
}
resolve();
});
}
module.exports = function (context, req) {
context.log('JavaScript HTTP trigger function processed a request.');
co(function*() {
try {
yield doPromise();
} catch(err) {
context.log(err);
context.done(err, null);
return;
}
context.log(context.bindings.res);
context.bindings.res = { body: 'Hey' };
context.done();
});
};
実行してみると、例外を捉えて、異常終了として終わるようになりました
2017-10-14T01:10:11 Welcome, you are now connected to log-streaming service.2017-10-14T01:11:11 No new trace in the past 1 min(s).
2017-10-14T01:11:14.654 Function started (Id=2c15d5f1-7a16-4179-87ad-67ebb5194fdb)
2017-10-14T01:11:15.173 JavaScript HTTP trigger function processed a request.
2017-10-14T01:11:15.180 error
2017-10-14T01:11:15.402 Exception while executing function: Functions.PromiseDemo. System.Private.CoreLib: Result: Exception: errorStack: .
2017-10-14T01:11:15.693 Function completed (Failure, Id=2c15d5f1-7a16-4179-87ad-67ebb5194fdb, Duration=1023ms)
"あれ?すぐ、終わるはずなのに動き続けてるなぁ。”とか疑問に思ったら、Promise内で例外を扱えていない可能性もあるので、気をつけましょう。
そして、事前にローカルで実行しておくと、Azure上で出てくる情報より多いので間違いに気づきやすくなると思います。