[Node.js] 미국 가버린 stacktrace를 찾아보자

부제: 비동기 호출 시 stacktrace가 유실되는 문제. javascript async stacktrace has lost

 Node.js는 single-thread 기반 비동기 방식이다. 그래서 나는 Node.js로 서버 애플리케이션을 개발할 때 Javascript가 ES6 이후로 지원하는 promise, async, await를 많이 사용한다. 나처럼 개발하는 사람들은 한 번쯤 직면 했을 문제에 대해 다뤄보려고 한다. 그건 바로..

비동기 호출 시 Error의 stacktrace가 사라지는 현상

 나는 서론을 쓰는데 재능이 없으니 바로 예제를 보여주겠다.

1. stacktrace가 없어지는 상황

async function functionOne() {

    throw new Error('Error here prints the complete stack');
  
    await new Promise((resolve) => {
      setTimeout(() => { resolve(); }, 1000);
    });
}
  
async function functionTwo() {
    await functionOne();
}

async function functionThree() {
    await functionTwo();
}

functionThree()
.catch((error) => {
    console.error(error);
});

functionThree()를 실행하면 three는 two를 실행하고 two는 one을 실행하며 one에서 Error를 강제로 발생시키는 간단한 예제이다. 위 예제를 돌려보면 결과는...

Error: Error here prints the complete stack

    at functionOne (~/Repositories/scriptExample/stacktrace1.js:3:11)

    at functionTwo (~/Repositories/scriptExample/stacktrace1.js:11:11)

    at functionThree (~/Repositories/scriptExample/stacktrace1.js:15:11)

    at Object.<anonymous> (~/Repositories/scriptExample/stacktrace1.js:18:1)

    at Module._compile (internal/modules/cjs/loader.js:688:30)

    at Object.Module._extensions..js (internal/modules/cjs/loader.js:699:10)

    at Module.load (internal/modules/cjs/loader.js:598:32)

    at tryModuleLoad (internal/modules/cjs/loader.js:537:12)

    at Function.Module._load (internal/modules/cjs/loader.js:529:3)

    at Function.Module.runMain (internal/modules/cjs/loader.js:741:12)

functionOne(), functionTwo(), functionThree()에서 오류가 발생했다는 stacktrace가 잘 노출 되었다. 이제 다음 예제에서는 stacktrace가 없어지는 상황을 재현할 것이다.

async function functionOne() {

    await new Promise((resolve) => {
        setTimeout(() => { resolve(); }, 1000);
    });

    throw new Error('Error here prints incomplete stack');
}

async function functionTwo() {
    await functionOne();
}

async function functionThree() {
    await functionTwo();
}

functionThree().catch((error) => {
    console.error(error);
});

 이번에는 functionOne()에서 await 함수 호출 이후 Error를 강제 발생 시켜봤다. 그 결과는?

Error: Error here prints incomplete stack

    at functionOne (~/Repositories/scriptExample/stacktrace2.js:7:11)

 Error stacktrace가 전부 미국가버렸다. 왜 이렇게 됐을까? 첫번째 예제와 두번째 예제를 잘 째려보면 두 예제의 차이에서 정답을 유추할 수 있다.

2. stacktrace가 미국가버린 이유

 첫번째 예제에서는 await 호출 전에 Error을 발생시켰고, 두번째 예제에서는 await 함수 호출 후에 Error를 발생 시켰다. 여기까지 분석하니 Call stack에서 분명 차이가 있을 것만 같다!!!

첫번째 예제 실행구조 슬라이드

01234

1. functionThree, functionTwo, functionOne 순으로 차곡차곡 Call stack에 쌓였다.

2. 오류가 발생해서 stacktrace가 잘 노출되었다.

두번째 예제 실행구조 슬라이드

012345678

1. functionThree, functionTwo, functionOne 순으로 차곡차곡 Call stack에 쌓였다.

2. setTimeout이 호출되고, Web API가 이를 수행한다.

3. functionOne, functionTwo, functionThree가 promise를 반환하고 Call stack에서 사라진다.

4. setTimeout이 끝나고 callback 함수가 Callback queue로 들어간다.

5. Event loop은 Call stack이 비어있음을 확인하고 callback 함수를 실행한다.

6. Error가 발생한다. 그런데 Call stack은 비어있다.

3. 사라진 stacktrace를 데려오는 법.

 예제 2의 패턴은 개발할 때 흔히 나오는 상황이다. 그래서 아무래도 그냥 지나치기에는 치명적인 문제인 것 같다. 다행히 많은 개발자들이 이에 대해 고민했고, 해결방법이 몇가지 나와있다.

방법1. node 12 이상을 사용한다.

 node 12버전부터 실행할 때 --async-stack-traces 라는 옵션을 줄 수 있다. 이 옵션을 줘서 실행하면 예제 2와 같은 상황에서도 stacktrace가 유지된다. 위에서 다룬 두번째 예제를 node v12.10.0 에서 실행해봤다.

Error: Error here prints incomplete stack

    at functionOne (~/Repositories/scriptExample/stacktrace2.js:7:11)

    at async functionTwo (~/Repositories/scriptExample/stacktrace2.js:11:5)

    at async functionThree (~/Repositories/scriptExample/stacktrace2.js:15:5)

 원하는 결과가 잘 나온 것 같다.

방법2. V8엔진에서 제공하는 Stack trace API를 재구현한다.

 V8엔진 개발자들도 미국 가버린 stacktrace를 찾는 우리가 안타까웠던 것이 틀림없다. 그래서 Error class에 stacktrace를 보관할 수 있는 기능을 하는 함수를 선언해놨다. (안타깝게도, 함수의 body가 없다.) 이 함수를 재구현하면 stacktrace를 유지할 수 있다.

 하지만 나도 직접구현해 본 적은 없다. 이미 나보다 똑똑한 사람들이 만들어 놓은 것이 많기 때문이다 ㅎ_ㅎ 추천하는 오픈소스 링크는 여기이다.

방법3. 비동기 호출시 stacktrace를 보관하는 함수를 직접 구현한다.

 슬슬 눈치채고 있을 것이다. 방법1,2,3 순으로 권장한다. 즉, 이 방법은 권장하지 않는 방법이다. 하지만 이런 방법이 있다는 것을 소개하자면.. 비동기 호출을 감싸는 함수를 직접 구현하여 stacktrace를 유지할 수 있다. 설명이 길어져야 별 도움이 안되니 빠르게 예제를 살펴보자.

const functionOne = wrap(async function functionOne() {
    await new Promise((resolve) => {
        setTimeout(() => { resolve(); }, 1000);
    });
    throw new Error('Error here prints incomplete stack');
});

const functionTwo = wrap(async function functionTwo() {
    await functionOne();
});

const functionThree = wrap(async function functionThree() {
    await functionTwo();
});

functionThree().catch((error) => {
    console.error(error);
});

function wrap(fn) {
    return function() {
        const originalErr = new Error();
        return fn.apply(this, arguments).catch(err => {
            err.stack += originalErr.stack;
            throw err;
        });
    };
}

 wrap이라는 함수를 추가했다. 이 함수는 파라미터로 함수를 받는다. 그리고 Error 객체를 하나 생성한 뒤 파라미터로 넘겨진 함수를 실행한다. 실행한 함수에서 오류가 발생한 경우 발생한 오류의 stacktrace에 직전에 생성한 Error의 stacktrace를 추가한다.

 이렇게하면 깨끗하진 않지만 stacktrace를 남길 수 있다. 위 예제를 실행한 결과는 다음과 같다.

Error: Error here prints incomplete stack

    at functionOne (~/Repositories/scriptExample/stacktrace2.js:5:11)Error

    at ~/Repositories/scriptExample/stacktrace2.js:22:27

    at functionTwo (~/Repositories/scriptExample/stacktrace2.js:9:11)

    at ~/Repositories/scriptExample/stacktrace2.js:23:17

    at functionThree (~/Repositories/scriptExample/stacktrace2.js:13:11)

    at ~/Repositories/scriptExample/stacktrace2.js:23:17

    at Object.<anonymous> (~/Repositories/scriptExample/stacktrace2.js:16:1)

    at Module._compile (internal/modules/cjs/loader.js:688:30)

    at Object.Module._extensions..js (internal/modules/cjs/loader.js:699:10)

    at Module.load (internal/modules/cjs/loader.js:598:32)

    at tryModuleLoad (internal/modules/cjs/loader.js:537:12)Error

    ... 후략

 지금까지 비동기 호출 시 stacktrace가 유실되는 상황에 대해 왜 발생하는지, 어떻게 해결할 수 있는지에 대해 다뤄봤다. 나는 JAVA/Spring 기반으로 개발을 시작해서 이런 상황이 발생하는지도 모르고 지나치다가 우연히 발견했다.

 이 글을 읽으시는 Node.js 개발자 분들은 stacktrace를 잘 살리셨으면(?) 좋겠다.

한줄요약

Node12 쓰세요

-끝-