안녕하세요? 이번 포스팅에서는 Node.js Runtime 앱 개발 시 필요한 디버깅을 해 보도록 하겠습니다.

애플리케이션 디버깅은 개발 시 피할 수 없는 사항으로 개발 시 발생하는 다양한 조건를 확인하고 오류 발생 시 명확한 원인을 찾기 위한 과정입니다. 그 방법중 가장 기본이 되는 것으로 로그 메시지를 이용 할 수 있습니다. 프로그래밍 언어를 배울 때 Hello World를 가장 먼저 작성하게 되는 것처럼 쉬우면서도 코드 중간 중간에 확인하고자 하는 내용을 넣은 후 프로그램 실행 시 출력되는 메시지를 확인하면서 오류를 잡아나갈 수 있는 강력한 디버깅 방법입니다.

Node.js의 메시지 함수

Node.js는 JavaScript 언어를 사용하는 Runtime 환경으로서 Web Browser에서의 JavaScript에서와 같이 표준 출력, 표준 에러 스트림으로 메시지를 출력할 수 있도록 console 객체를 제공하며, 다음과 같은 종류의 함수를 호출 할 수 있습니다.

  • console.assert(value[, message][, …args])

assert 함수는 특정 조건이 맞지 않는 경우 AssertError를 발생하며, 이 때 정해진 형식의 오류 메시지를 보여주는 경우에 사용합니다. Error가 생성되하므로 해당 함수를 try-catch로 처리하지 않는 경우 앱이 종료되며 표준 오류로 오류 메시지가 출력됩니다.

console.assert(false, 'Whoops %s', 'didn\'t work');
  • console.dir(obj[, options])

입력 받은 object에 대해 util.inspect()를 사용하고 그 결과를 표준 출력으로 보냅니다.

var obj = {'key':'value'};
console.assert(obj);
  • console.error([data][, …args])

입력 받은 메시지를 new line 문자와 함께 표준 오류로 내보냅니다.

const code = 5;
console.error('error #%d', code);
  • console.info([data][, …args])

입력 받은 메시지를 표준 출력으로 내보내는 console.log와 동일한 기능입니다.

  • console.log([data][, …args])

입력 받은 메시지를 new line 문자와 함께 표준 출력으로 내보냅니다.

const code = 5;
console.log('error #%d', code);
  • console.time(label)

time 함수는 timeEnd 함수와 함께 특정 기능이나 동작의 수행 시간을 계산할 때 사용합니다. time 함수에 전달하는 라벨 값을 ID로 해서 특정하고자 하는 시작 지점에서 호출하면 타이머가 시작합니다.

  • console.timeEnd(label)

timeEnd 함수는 time 함수와 함께 특정 기능이나 동작의 수행 시간을 계산할 때 사용합니다. time 함수에 전달했던 라벨 값과 동일한 라벨을 입력하면 타이머가 종료되면서 time 함수가 호출되었던 시간 부터 timeEnd 함수가 호출된 시간까지 밀리초 단위로 계산하여 표준 출력으로 내보냅니다.

참고로 Node.js v6.0.0 부터 timeEnd 함수가 호출되면 내부에 ID로 생성된 타이머가 삭제됩니다. 동일한 ID로 timeEnd가 두 번 이상 호출되는 경우 경고 문구가 출력됩니다.

  • console.trace(message[, …args])

‘Trace: ‘로 시작하는 메시지와 함께 trace함수가 호출 된 시점의 Stack 정보를 표준 오류로 내보냅니다.

  • console.warn([data][, …args])

입력 받은 메시지를 표준 오류로 내보내는 console.error와 동일한 기능입니다.

추가로, Node.js에서는 표준 출력, 표준 오류로 연결되어 있는 console 객체 대신 사용자가 정의한 출력 가능한 스트림을 지정해서 사용 할 수 있도록 Console 클래스도 지원합니다. 아래와 같이 getStreamSomehow이 Writable 스트림 인스턴스를 가져오는 함수라고 가정하면 다음과 같은 형식으로 사용 할 수 있습니다.

const out = getStreamSomehow();
const err = getStreamSomehow();
const myConsole = new console.Console(out, err);

myConsole.log('Hello, World')

메시지 형식

Node.js에서 console를 이용하여 메시지를 출력하면 util.format() 함수의 기능일 이용한 텍스트 형식을 이용할 수 있습니다.

예를 들어 Hello, World와 같은 고전 문장을 표준 출력으로 나타내려면 아래와 같이 사용합니다.

console.log('Hello World');

만약 문자열을 출력하는 경우라면

var world = 'World';
console.log('Hello ' + world);

또는 다음과 같이 콤마(‘,’)를 이용하면 자동으로 공백 문자로 연결해서 출력됩니다.

var world = 'World';
console.log('Hello', world);

특정 문자열을 치환하고자 한다면 다음과 같이 %문자를 이용한 치환 형식을 이용해 볼 수 있습니다.

var world = 'World';
console.log('Hello %s', world);

또한, Node.js v4 이상의 경우 ES6를 지원하므로 다음과 같이 Template Literal 기능을 이용 할 수 있습니다.

var world = 'World';
console.log(`Hello ${world}`);

치환 형식에 더 상세한 내용은 util.format(format[, …args])‘과 Template literals를 참고하기 바랍니다.

로그 메시지 확인하기

앞서 애플리케이션 코드에서 로그 메시지를 어떻게 출력하는지 알아 보았습니다. 이제는 그 메시지를 어떻게 확인 할 수 있는지 알아보겠습니다.

Node.js를 PC와 같은 개인 환경이서 실행하는 경우 실행 node runtime을 실행했던 터미널 명령창 또는 DOS창에 그 메시지가 나타나게됩니다. 그렇데 Cloud 환경인 Bluemix에서 실행 중인 앱은 어디서 확인 할 수 있을까요?

Bluemix 앱이 실행 중에 출력되는 로그 메시지는 세 가지 방법으로 확인 해 볼 수 있습니다.

  • Bluemix Dashboard에서 로그 메시지 확인
  • 터미널 명령창에서 Bluemix CLI로 로그 메시지 확인
  • 외부 로그 시스템을 통한 메시지 확인

Bluemix Dashboard에서 로그 메시지 확인

Bluemix에 애플리케이션이 잘 배포되었다면, Bluemix Dashboard 웹에서 해당 앱에 대한 서비스 연결 정보와 더불어 로그 메시지를 보여주는 메뉴가 있습니다. 대시보드 앱의 로그 메뉴를 선택하면 아래와 같이 과거 앱이 출력한 로그와 현재 출력되는 내용을 볼 수 있습니다.

debug_dashboard

dashboard_logview

필요에 따라 오류 메시지만 따로 보거나 로그 메시지 유형, 특정 인스턴스가 출력하는 로그 정보 등을 따로 필터링해서 볼 수 있는 기능을 제공합니다.

터미널 명령창에서 Bluemix CLI로 로그 메시지 확인

Bluemix Dashboard에서 확인한 방법이 웹브라우저를 이용한 방법이라면, Bluemix CLI(Command Line Interface )는 명령창에서 명령어를 직접 입력하는 방법입니다. Bluemix는 Cloud Foundary 를 기반으로 하므로 CF 명령 수행이 가능한 CLI를 배포하고 있습니다.

https://console.ng.bluemix.net/docs/cli/index.html#downloads에서 받아 설치 후 명령창에서 이용해 볼 수 있는데, Bluemix 서버와 연결을 위해 가장 먼저 cf login 명령으로 Bluemix 서비스에 로그인을 해야 정상적인 서비스를 이용할 수 있습니다.

cf login

debug_cf_login

login시 회원 가입했던 email 및 비밀번호를 입력하고나면 organization과 work space를 선택하도록 되어 있습니다. 배포한 앱이 있는 곳을 선택합니다.

그리고 현재 계정에 배포되어 있는 애플리케이션 정보를 다음 명령으로 확인 해 볼 수 있습니다.

cf apps

debug_cf_apps

이제 cf logs 명령으로 앱의 로그 메시지를 확인해 볼 수 있습니다.

cf logs <app_name>

단, cf logs 명령을 이용하면 해당 시점 이후 부터 로그 메시지가 발생할 때 출력이 됩니다. 만약 Dashboard에서처럼 최근 출력된 메시지를 보려면 아래와 같이 –recent 옵션을 추가하는 방법을 이용합니다.

cf logs </app_name><app_name> --recent

debug_cf_logs_recent

참고로, Bluemix CLI 중 CF 명령에 대한 자세한 내용은 다음 명령 또는 CF 명령에 대한 문서
를 참고하기 바랍니다.

cf --help

debug_cf_help1

외부 로그 시스템을 통한 메시지 확인

Bluemix 앱이 생성하는 로그 정보는 단순히 메시지 출력 뿐만 아니라 생성 시간, 메시지를 생성한 컴포넌트, 스트림 타입 정보도 같이 포함되어 있습니다.
이 정보를 분석용 데이터로 사용하고자 하거나 7일로 제한된 Bluemix에서 로그 저장 기간 보다 더 많은 정보를 저장해야 하는 경우 별도의 로깅 시스템(Splunk와 같은)을 구성하여 사용할 수 있습니다.
이 방법에 대한 정보는 https://console.ng.bluemix.net/docs/monitor_log/monitoringandlogging.html에서 확인 할 수 있으며, 이후 Log drain 항목으로 다루도록 하겠습니다.

참고