Azure Functions의 Node.js Promise에서 reject하지 않으면 좀비가됩니다.

Azure Functions를 사용하기 시작하고 익숙하지 않은 Node.js로 작성하는 동안 우연히 발견 된 문제에 대해.

동기 처리를 하고 싶기 때문에, 아이 과 Promise 를 조합해 구현하고 있었던 중, Promise 내에서 예외 처리를 대응할 수 없고 reject 를 호출하지 않고 종료해 버렸습니다. 그러면 시작된 Function이 끝나지 않고 살아남습니다

재현 방법

빨리 재현하기 위한 코드를 써 보았습니다.

PromiseDemo/index.js

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 를 실행합시다, 라고 하는 것.

앞의 예를 다시 작성하면 다음과 같은 느낌으로.

PromiseDemo/index.js

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상에서 나오는 정보보다 많기 때문에 실수를 눈치채기 쉬워진다고 생각합니다.