Node.jsアプリで問題判別のためのファースト・ステップ on Bluemix

はじめに

最近Bluemix Platform(PaaS)のCloud Foundryにおいて、Node.jsで実装されたアプリケーションを開発/運用していく中で、アプリケーションに何がしかの問題が発生したときに大した情報が残らず、問題判別に困るケースをよく見かけます。

もちろん、Bluemixは簡単にアプリの実行環境を用意できるので、問題に気づいたら別途再現環境を用意して問題判別していけば良いのですが、お客様に何が起こったかを報告するためにも最低限何か仕込んでおけるものがないかなと考えることが多いと思います。

また、Cloud Foundry特有の「ダンプしても自動で再起動がかかると問題判別用のファイルが失われる」問題が発生するので、そもそもどうするの?という質問もBluemixを使っているとよく聞かれます。

そこで今回は、Bluemix上でのNode.jsアプリケーション(IBM SDK for Node.jsのビルドパックを利用したCloud Foundryアプリケーション)を動かす前提で、問題判別に向けたライブラリーとそのセットアップ方法を整理しておこうと思った次第です。

以下のリンクを参考にまとめています。わかりやすくまとまっているので、まずはこちらを見ていただくことをお勧めします。

Diagnostic dumps for Node.js applications in Bluemix
https://developer.ibm.com/node/2017/03/28/diagnostic-dumps-node-js-applications-bluemix/

以下長文ですが、上記のリンクを元に、実際に実機で動かしてみての注意事項も記載しておきましたので、問題判別したい時の取り掛かりとして参考になれば幸いです。

障害のレポート出力 ~ node-report

どういうもの?

例えばBluemixで利用可能なLiberty for Java, 実装としてWebSphere Application Server Liberty ProfileというIBM提供のJavaアプリケーション・サーバーにはFFDC(初期障害データ・キャプチャー)という機能があって、エラーの簡易な問題判別に利用できる情報を提供する仕組みがあります。これと似たような仕組みで、エラーが発生したらとりあえず人間が読める形で必要な情報を出力できる機能を提供するNode-Reportライブラリーが公開されています。

GitHub - odejs/node-report
https://github.com/nodejs/node-report

サポートされるNode.jsのバージョンはv4,v6,v7で、OSはAIX, Linux, MacOS, SmartOS, そしてWindowsとのこと。Bluemix上で利用可能なIBM SDK for Node.jsでも当然使えます。

レポート出力のトリガーは以下の4種類で、必要に応じて不要なものを外すことが可能です:
- JavaScriptのException
- Out of MemoryなどのFatalError
- SIGQUIT(キーボードによる中止), SIGUSR2(ユーザー定義)シグナルでのプロセスのKill (Windowsはサポート外)
- レポート出力のAPIをコール (triggerReport(),getReport())

Bluemix上でのセットアップ

まずはpackage.jsonのdependenciesに「node-report」追加します。

{
  "name": "demo",
  "dependencies": {
    "node-report": "2.1.x",
    :
  }
}

あるいは2017年5月5日以降の最新のIBM SDK for Node.js v3.12以降であれば、scriptsのstartキーに「node -r node-report <アプリ・ファイル>」を指定してあげる設定でもnode-reportが利用可能です。

{
  "name": "demo",
  :
  "scripts": {
    "start": "node -r node-report app.js"
  },
  :
}

あとはアプリケーションのファイル(app.jsなど実行したいファイル)に以下のような宣言を記載すれば良いです：

require('node-report');
var http = require("http");

function my_listener(request, response) {
  switch (request.url) {
   :
  }
}

var http_server = http.createServer(my_listener);
http_server.listen(8080);

以上で設定は終了で、あとはcf pushするだけです。コードを汚さず簡単に設定できますね。

基本的にはアプリケーションがクラッシュしてしまうと(Cloud Foundry側がそう判断してしまうと)、レポートをファイルに吐いても確認できずにランタイムが再生成されてしまうので、確認できずに終わってしまいます。そこで、平常運用時は環境変数NODEREPORT_FILENAMEでstdoutあるいはstderrを指定しておいて、一旦標準出力/エラーに出力しておくと良いと思います。

出力例

以下のような形です。問題判別に向けて最低限欲しい環境情報は出力されている感じですかね。

====================================================
==== Node Report ======================================
(どのようなイベントが発生したかのサマリーと環境情報)
Event: Allocation failed - JavaScript heap out of memory, location: "CALL_AND_RETRY_LAST"
Filename: node-report.20170516.011245.67465.001.txt
Dump event time: 2017/05/16 01:12:45
Module load time: 2017/05/16 01:11:53
Process ID: 67465
Command line: node app.js

Node.js version: v7.6.0
(ares: 1.10.1-DEV, cldr: 30.0.3, http_parser: 2.7.0, icu: 58.2, modules: 51,
openssl: 1.0.2k, tz: 2016j, unicode: 9.0, uv: 1.11.0, v8: 5.5.372.40, zlib: 1.2.11)

node-report version: 2.1.2 (built against Node.js v7.6.0)

OS version: Darwin 16.5.0 Darwin Kernel Version 16.5.0: Fri Mar 3 16:52:33 PST 2017; root:xnu-3789.51.2~3/RELEASE_X86_64

Machine: XXX-no-MacBook-Pro.local x86_64

====================================================
==== JavaScript Stack Trace ==============================
(JavaScriptのスタック・トレース)
No stack trace available

====================================================
==== Native Stack Trace =================================
(ネイティブ・スタック・トレース)
0: [pc=0x1022cb9c7] nodereport::OnFatalError(char const*, char const*) [/Users/seiichiro/projects/PD/node-report/demo/node_modules/node-report/api.node]
1: [pc=0x100144a34] v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [/usr/local/bin/node]
2: [pc=0x1005321ee] v8::internal::Factory::NewUninitializedFixedArray(int) [/usr/local/bin/node]
3: [pc=0x1004ffc81] v8::internal::(anonymous namespace)::ElementsAccessorBase >::GrowCapacity(v8::internal::Handlev8::internal::JSObject, unsigned int) [/usr/local/bin/node]
4: [pc=0x1007b7d0b] v8::internal::Runtime_GrowArrayElements(int, v8::internal::Object*, v8::internal::Isolate) [/usr/local/bin/node]
5: [pc=0x3d5a42a043a7]

====================================================
==== JavaScript Heap and Garbage Collector ==================
(問題発生時のヒープの状態)
Heap space name: new_space
Memory size: 1,048,576 bytes, committed memory: 62,464 bytes
Capacity: 1,031,168 bytes, used: 45,056 bytes, available: 986,112 bytes
Heap space name: old_space
Memory size: 1,523,421,184 bytes, committed memory: 1,523,378,608 bytes
Capacity: 1,498,054,976 bytes, used: 1,497,868,168 bytes, available: 186,808 bytes
Heap space name: code_space
Memory size: 1,105,920 bytes, committed memory: 794,688 bytes
Capacity: 735,904 bytes, used: 735,904 bytes, available: 0 bytes
Heap space name: map_space
Memory size: 544,768 bytes, committed memory: 301,824 bytes
Capacity: 226,248 bytes, used: 226,248 bytes, available: 0 bytes
Heap space name: large_object_space
Memory size: 249,245,696 bytes, committed memory: 249,245,696 bytes
Capacity: 249,233,328 bytes, used: 249,233,328 bytes, available: 0 bytes

Total heap memory size: 1,775,366,144 bytes
Total heap committed memory: 1,773,783,280 bytes
Total used heap memory: 1,748,108,704 bytes
Total available heap memory: 1,172,920 bytes

Heap memory limit: 1,501,560,832

====================================================
==== Resource Usage ===================================
(CPU等のリソース使用状況)
Process total resource usage:
User mode CPU: 45.067794 secs
Kernel mode CPU: 1.098624 secs
Maximum resident set size: 1,858,739,372,032 bytes
Page faults: 14 (I/O required) 590932 (no I/O required)
Filesystem activity: 0 reads 2 writes

====================================================
==== Node.js libuv Handle Summary =========================
(I/O処理のイベントを管理するライブラリ「libuv」の処理サマリー)
(Flags: R=Ref, A=Active)

Flags Type Address
[-A] async 0x0x101576ee8
[--] check 0x0x7fff5fbfea48
[R-] idle 0x0x7fff5fbfeac0
[--] prepare 0x0x7fff5fbfebb0
[--] check 0x0x7fff5fbfec28
[--] idle 0x0x7fff5fbfeb38
[-A] async 0x0x1022d0e98
[R-] timer 0x0x7fff5fbfecb8
[RA] tcp 0x0x102702a00
[R-] tty 0x0x102702fb0
[-A] signal 0x0x1027024b8
[R-] tty 0x0x102703a60
[RA] timer 0x0x102704228
[RA] tcp 0x0x1023188a0
[-A] timer 0x0x102318d68
[RA] tcp 0x0x102603ca0

====================================================
==== System Information =================================
(OSの環境変数やulimitの値、ロードしているライブラリを表示)
Environment variables
TERM_PROGRAM=Apple_Terminal
:
OLDPWD=/Users/seiichiro/projects/PD/node-report

Resource limits soft limit hard limit
core file size (blocks) 0 unlimited
data seg size (kbytes) unlimited unlimited
file size (blocks) unlimited unlimited
max locked memory (bytes) unlimited unlimited
max memory size (kbytes) unlimited unlimited
open files 10240 unlimited
stack size (bytes) 8388608 67104768
cpu time (seconds) unlimited unlimited
max user processes 709 1064
virtual memory (kbytes) unlimited unlimited

Loaded libraries
/usr/local/bin/node
:
====================================================

利用にあたって注意すること

• 標準出力/エラーにレポートを出力する際には出力する順番に注意
  cf logsでレポートが確認できるように設定できますが、ログ・ストリームでは出力順が保証されません。ただ、何が発生したかを知るきっかけにはなると思いますので、設定しておくのが良さそうかなというのが個人的な見解です。

• ファイル出力する場合は、アプリケーション管理ユーティリティーを有効化
  真面目に問題判別する必要が出てきたら、Bluemixで提供するアプリケーション管理ユーティリティーを有効化します。詳しくは「障害が発生しても稼働したままにする ~ アプリケーション管理ユーティリティー」を参照してください。その場合、node-reportライブラリーはpackage.jsonのdependenciesで指定してください。

• ファイル形式でのデータ収集方法
  ファイルで出力されたレポートを収集する際には以下のようなcf sshコマンドで対象のランタイムにログインして、収集することになります。

'cf ssh <アプリケーション名> -c "cat ./app/node-report-xxxx.txt" > node-report-xxxx.txt'

障害が発生しても稼働したままにする ~ アプリケーション管理ユーティリティー

どういうもの?

Cloud Foundryの場合、冒頭でも述べたようにランタイムがクラッシュすると自動的に再起動する動作を取ります。この動作は自動復旧という観点では有益なのですが、問題判別の観点では確認したいファイル群が失われてしまう、など邪魔なケースがあります。こうした状態を解決する方法としてBluemixではアプリケーション管理ユーティリティーが提供されています。

アプリケーション管理ユーティリティーはLiberty for JavaあるいはIBM SDK for Node.jsでのみ利用可能なフィーチャーです。別言語では利用できない点に注意してください。

Bluemix上でのセットアップ

セットアップは簡単で、環境変数BLUEMIX_APP_MGMT_ENABLEをセットアップすれば良いです。オプションはいろいろあるのですが、最低限以下の設定を加えて再ステージを行えば良いです。

cf set-env <アプリケーション名> BLUEMIX_APP_MGMT_ENABLE proxy
cf restage <アプリケーション名>

この設定で、ランタイムの中で自身のアプリケーションの前段にproxyアプリケーションが導入され、実行されます。自身のアプリケーションが何がしかでクラッシュした場合でもproxyアプリケーションさえ生きていればランタイムは止まらず動作し続ける、そんな仕組みになっています。

利用にあたって注意すること

• アプリケーション管理ユーティリティーはインスタンス1つの状態で使用すること
  トンデモ仕様ですが、気をつけましょう。
• 本番環境では使用しないこと
  あくまでもデバッグ目的なので、本番での常時利用は控えましょう。
• nodeコマンドのオプションの指定に注意すること
  2017年5月時点ではpackage.jsonのscriptsのstartに「node -r app.js」などのコマンドを指定して起動しようとすると、アプリケーション管理ユーティリティーが導入されないという罠がありますので、注意しましょう。

2017-05-16T10:51:25.76+0900 [STG/0] OUT -----> Installing App Management
2017-05-16T10:51:25.84+0900 [STG/0] OUT -----> Caching build
2017-05-16T10:51:25.84+0900 [STG/0] OUT WARN: App Management cannot be installed because the start script cannot be found.
2017-05-16T10:51:25.84+0900 [STG/0] OUT To install App Management utilities, specify your 'node' start script in 'package.json' or 'Procfile'.

ヒープダンプを取得する ~ node-heapdump

どういうもの?

問題判別時にNode.jsのV8のメモリーのスナップショットを取得して、問題解析を行いたいケースが多々あると思います。こうした場合にはnode-heapdumpライブラリーを使います。JSONフォーマットで取得したタイミングのヒープのスナップショットが取得できます。

GitHub - bnoordhuis/node-heapdump
https://github.com/bnoordhuis/node-heapdump

Bluemix上でのセットアップ

Bluemix上で利用する際にはアプリケーション管理ユーティリティーは有効化してからのスタートをお勧めします。以下有効化している前提で記載します。

まずはpackage.jsonのdependenciesに「heapdump」を追加します。

{
  "name": "demo",
  :
  "dependencies": {
    "heapdump": "0.3.x"
    :
  }
}

あるいは2017年5月5日以降の最新のIBM SDK for Node.js v3.12以降であれば、scriptsのstartキーに「node -r heapdump <アプリ・ファイル>」を指定してあげる設定でもnode-heapdumpが利用可能です。

{
  "name": "demo",
  :
  "scripts": {
    "start": "node -r node-report app.js"
  },
  :
}

次にアプリケーションのファイル(app.jsなど実行したいファイル)に以下のような宣言を記載します：

require('heapdump');
var http = require("http");

function my_listener(request, response) {
  switch (request.url) {
   :
    heapdump.writeSnapshot();
  }
}

var http_server = http.createServer(my_listener);
http_server.listen(8080);

最後に、アプリケーション・ファイルと同じディレクトリに.profile.d/ulimit.shを作成します。実行権限を与えておくことを忘れずに。

#!/bin/bash
echo "Setting core dump size limit to unlimited"
ulimit -c unlimited

あとはcf pushすれば良いです。

ヒープダンプを任意のタイミングで取得したいならcf sshでログインし、プロセスに対しSIGABRTシグナルでkillすれば良いです。

利用にあたって注意すること

• ulimitの設定に注意
  デフォルトではulimitのcore file sizeが0のため、適切にダンプが出力できないです。必ずulimitの変更スクリプトを差し込んで実行すると良いかなと思います。

• 利用する場合は、アプリケーション管理ユーティリティーを有効化
  node-reportと同様、確実にヒープダンプを取得するなら、Bluemixで提供するアプリケーション管理ユーティリティーを有効化します。詳しくは「障害が発生しても稼働したままにする ~ アプリケーション管理ユーティリティー」を参照してください。

• アプリケーション管理ユーティリティーを有効化するので、インスタンスは1つで実施
  トンデモ仕様にひきづられますが、確実に取得したいなら1インスタンスで実施してください。

• Out of Memory時、Uncaught Exception時のヒープダンプの自動取得はできない
  試せていませんが、そうらしいです。

コアダンプを取得する ~ 「--abort-on-uncaught-exception」オプション

どういうもの?

Out of Memoryや Uncaught exceptions発生時にコアダンプを取得したい場合に「--abort-on-uncaught-exception」オプションを指定することで取得可能になります。
Bluemixで提供するアプリケーション管理ユーティリティーを有効化した前提で設定を検討します。

Bluemix上でのセットアップ

Bluemix上で利用する際にはアプリケーション管理ユーティリティーを有効化している前提で、package.jsonのscriptsのstartキーに「node --abort-on-uncaught-exception <アプリ・ファイル>」を指定します。

{
  "name": "demo",
  :
  "scripts": {
    "start": "node --abort-on-uncaught-exception app.js"
  },
  :
}

そして、コアダンプを吐く際にディスク領域が足りないと、、な状況もあると思うので、事前にランタイムに割り当てるディスク・クォータを変更します。デフォルトは1024MBなので、最大の2048MBに変更しておきましょう。アプリケーションがすでにpushされているなら以下のコマンドで変更してください。

cf scale <アプリケーション名> -k 2G

利用にあたって注意すること

• アプリケーション管理ユーティリティーを有効化するので、インスタンスは1つで実施 トンデモ仕様にひきづられますが、確実に取得したいなら1インスタンスで実施してください。

インスタンスをモニターする ~ appmetrics-dash

どういうもの?

実行しているNode.jsアプリケーションのヒープ使用状況などを以下のように可視化するモニター画面を提供してくれるライブラリーの１つが「appmetrics-dash」です。

GitHub - RuntimeTools/appmetrics-dash
https://github.com/RuntimeTools/appmetrics-dash

前述したNode.jsのレポート出力やヒープダンプをモニター画面の左下にあるボタンからクリックして取得することが可能です。メモリーの振る舞いが変になってきたタイミングで取得する、という要件に対して活躍できそうです。

Bluemix上でのセットアップ

まずはpackage.jsonのdependenciesに「appmetrics-dash」追加します。

{
  "name": "demo",
  "dependencies": {
    "appmetrics-dash": "3.1.x",
    :
  }
}

次にアプリケーションのファイル(app.jsなど)に以下のような宣言を記載します：

var dash = require('appmetrics-dash');
dash.attach();
var http = require("http");

function my_listener(request, response) {
  switch (request.url) {
   :
  }
}

var http_server = http.createServer(my_listener);
http_server.listen(8080);

以上でセットアップ完了です。cf pushすれば、「https://<アプリケーションのFQDN>/appmetrics-dash」でモニター画面を開くことができます。

利用にあたって注意すること

• インスタンスは1つで利用するのが適切である
  Cloud Foundryの場合、インスタンスが複数でアプリケーションを動かしている場合はラウンドロビンで各インスタンスにリクエストを割り振りますので、特定のインスタンスめがけてモニター画面を出す、みたいなことは基本的にできないと考えて利用した方が2017年5月時点では良さそうです。

最後に

長々と書いてしまいましたが、通常運用時はnode-reportを標準出力/エラーで出しておいて、問題発生後のきちんとした問題判別時にheapdumpなどを取得していくスタイルでまずは進めるのが良いかと思います。

小分けにして記事を稼げば良かったかなとも後悔してます。。
意外と書くことがあったので、許してください。

そのうちこれらを用いてどう問題判別を進めていくかを問題判別スキルが上がってきたらまとめていきたいです。