人力検索はてな
モバイル版を表示しています。PC版はこちら
i-mobile

node.jsのチャットサービスのプロセスが落ちる原因が特定できません。

node.jsとsocket.ioでチャットを運営しています。
1日に2?3回nodeのプロセスが落ちてるのですが、原因が特定できず解决できません。

現在は、毎分cronでnodeのport(3001)にアクセスできるか調べて、
アクセスできなければ落ちていると判断し、下記のコマンドを実行して立ち上げています。

node app.js > node_(日付).log /dev/null &

何かエラーでプロセスが落ちた場合には、ログファイルに書き出されるかと思いましたが、
node_(日付).logの中身は
info - socket.io started
だけしか残っていません。

nodeのプロセスが落ちる理由の特定方法や、
可能性のある原因があれば教えて下さい。

環境は以下の通りです。
-------------------------------
node.js v0.6.8
socket.io 0.8.7
socketの最大同時接続数 約200人
Centos 5.7

よろしくお願いします。



●質問者: araishi
●カテゴリ:ウェブ制作
○ 状態 :終了
└ 回答数 : 3/3件

▽最新の回答へ

1 ● y-kawaz
●100ポイント ベストアンサー

まず、起動の仕方に問題があります。それだと標準出力は保存されますが標準エラー出力は保存されません。以下のように起動したほうが良いです。

node app.js > node_(日付).log 2>&1 &


キャッチされない例外が発生したときは process のuncaughtExceptionで捕まえられます。
ここでログを吐くようにするとなにか原因がわかるかもしれません。
また、uncaughtException で例外を補足しても再度throwしなければプロセスは動き続けてくれるので根本解決ではありませんが勝手に落ちるのを防げるケースもあります。

process.on('uncaughtException', function (err) {
 console.log('uncaughtException => ' + err);
});


あとは後は何もログを残さず終了するとのことなので、SWAPがない環境などではメモリ不足によってカーネルに殺された可能性もあるかもしれません。


後ありがちなのが1プロセスがオープンできるファイル数(TCP接続数なども含む)の上限に達してる可能性もあります。ulimit -n で上限の数字を確認できます。
もしこの上限に引っかかっている場合は、rootでしか出来ませんが ulimit -n 999999 などと実行しておくと上限の数字を増やすことが出来ます。コレを実行した後に、もう一度ulimit -nすると999999に上がっていることが確認できるでしょう。


araishiさんのコメント
ご回答ありがとうございます。 オープンできるファイル数が5000だったので、ulimit -n 999999として増やしました。 まずこの時点で修正できているか確認するためnodeを再起動してみましたが、9時間後にプロセスが落ちていました。 app.jsにuncaughtExceptionの処理を追記し、 process.on('uncaughtException', function (err) { console.log('uncaughtException => ' + err); }); 起動するコマンドを下記に変更しました。 node app.js > node_(日付).log 2>&1 & しばらく様子を見ていると、ログファイルに uncaughtException => TypeError: Cannot read property 'address' of undefined と数行出力されていました。 ただその時にチャットのページが表示されなく(404ではなく白紙のページが出力されるような感じに)なってしまいましたので、 現在はuncaughtExceptionの処理を削除し様子を見ているところです。

araishiさんのコメント
プロセスが落ちる原因は、 TypeError: Cannot read property 'address' of undefined というエラーで、下記の部分が問題だったようです。 io.sockets.on('connection', function(socket) { console.log(socket.handshake.address.address); }) socket.handshake.address.addressが未定義になる理由はまだわかっていませんが、原因の特定できたのでこの質問は終了いたします。ありがとうございました。

2 ● taroe
●100ポイント

メモリーの使用量を確認してみては?
メモリー不足になると、落ちそうな気がします。

もしかすると、メモリ?リークしてるとか。


araishiさんのコメント
ご回答ありがとうございます! VPSサーバーでメモリは8Gあります topコマンドでみてみました。 --- PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3092 user 15 0 881m 83m 6224 S 6.0 1.0 8:25.28 node --- 1.0%なんですが、1.0?1.5のあたりをうろうろしていますので メモリは大丈夫そうかもしれません。

a-kuma3さんのコメント
VIRT の 881m が、そのプロセスが使ってる仮想メモリですけど、 その値が単純に増加していくようだと、リークを起こしてます。 y-kawaz さんが、ulimit の話をしてましたけど、プロセスサイズにも ulimit で制限をかけられます。 大丈夫だとは思いますけどね。

araishiさんのコメント
ご回答ありがとうございます。 topコマンドもよくわかってなかったみたいではずかしいです。 ulimit -aを実行してみました。 core file size (blocks, -c) 0 data seg size (kbytes, -d) unlimited scheduling priority (-e) 0 file size (blocks, -f) unlimited pending signals (-i) 69632 max locked memory (kbytes, -l) 32 max memory size (kbytes, -m) unlimited open files (-n) 999999 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 10240 cpu time (seconds, -t) unlimited max user processes (-u) 69632 virtual memory (kbytes, -v) unlimited file locks (-x) unlimited

a-kuma3さんのコメント
そうやって、みんな大きくなっていくんだって =)

3 ● a-kuma3
●100ポイント

y-kawaz さんが書かれているように、標準エラー出力を見れば、多分、解決のような気がします。

もし、Node.js が正しく例外処理ができなくて、javascript の例外が出ずに、ズドンと落ちているような場合には、
strace を取っておくと、解決の手がかりになるかもしれません。

strace は、システムコールの何を呼んだか、とか、どんなシグナルが発生したか、ということが分かります。

% strace -p プロセスID

かなり、ずらずらと出力されるので、何かのファイルにリダイレクトしておくと良いかも。
指定したプロセスID のプロセスがいなくなると、シェルに制御が戻ります。

プロセスID は、アンパサンドをつけて Node.js を起動したときの、ログインシェルの標準出力に表示されますが、もし、自動で再起動してるから、よく分からない、ということであれば、
ps の出力から探すか、lsof で該当のポートをつかんでいるプロセスを探します。

% lsof -i:3001


メモリリークを起こしているかどうかは、ps の出力を随時、確認するか、top で見ていれば分かります。


araishiさんのコメント
ご回答ありがとうございます。 プロセスIDは起動時に控えていたので、 strace コマンドを実行してみました。 初めて使ったのですが、内容は下記のものがたくさんでてきました。 ---------------------- write(245, "\20165:::{\"name\":\"setup\",\"args\":[{\""..., 56) = 56 write(93, "\20165:::{\"name\":\"setup\",\"args\":[{\""..., 56) = 56 write(197, "\20165:::{\"name\":\"setup\",\"args\":[{\""..., 56) = 56 gettimeofday({1335429186, 840886}, NULL) = 0 write(263, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 futex(0xfe49538, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1335429186, 841672}, NULL) = 0 write(120, "HTTP/1.1 200 OK\r\nContent-Type: t"..., 158) = 158 gettimeofday({1335429186, 841905}, NULL) = 0 write(120, "", 0) = 0 gettimeofday({1335429186, 842214}, NULL) = 0 gettimeofday({1335429186, 842456}, NULL) = 0 write(264, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 gettimeofday({1335429186, 843026}, NULL) = 0 write(218, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 gettimeofday({1335429186, 843424}, NULL) = 0 write(194, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 gettimeofday({1335429186, 843706}, NULL) = 0 write(73, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 futex(0xfe49538, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1335429186, 844292}, NULL) = 0 write(160, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 gettimeofday({1335429186, 844544}, NULL) = 0 write(179, "HTTP/1.1 200 OK\r\nContent-Type: t"..., 158) = 158 gettimeofday({1335429186, 845034}, NULL) = 0 write(179, "", 0) = 0 gettimeofday({1335429186, 845252}, NULL) = 0 write(58, "\20165:::{\"name\":\"setup\",\"args\":[{\""..., 56) = 56 gettimeofday({1335429186, 845623}, NULL) = 0 write(152, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 gettimeofday({1335429186, 846078}, NULL) = 0 write(150, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 gettimeofday({1335429186, 846469}, NULL) = 0 write(56, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 write(282, "\20165:::{\"name\":\"setup\",\"args\":[{\""..., 56) = 56 gettimeofday({1335429186, 847102}, NULL) = 0 write(276, "57\r\n<script>_(\"5:::{\\\"name\\\":\\\"s"..., 93) = 93 clock_gettime(CLOCK_MONOTONIC, {951633, 377500379}) = 0 epoll_wait(4, {}, 64, 0) = 0 clock_gettime(CLOCK_MONOTONIC, {951633, 377621379}) = 0 gettimeofday({1335429186, 849306}, NULL) = 0 gettimeofday({1335429186, 849488}, NULL) = 0 write(26, "1a\r\n<script>_(\"2::\");</script>\r\n", 32) = 32 gettimeofday({1335429186, 849730}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {951633, 378317379}) = 0 epoll_wait(4, {{EPOLLIN, {u32=120, u64=1219770712184}}}, 64, 195) = 1 clock_gettime(CLOCK_MONOTONIC, {951633, 387261379}) = 0 read(120, "GET /socket.io/1/xhr-polling/140"..., 65536) = 733 futex(0xfe49538, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1335429186, 859315}, NULL) = 0 futex(0xfe49538, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1335429186, 861529}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {951633, 390309379}) = 0 epoll_wait(4, {{EPOLLIN, {u32=103, u64=1769526526055}}}, 64, 183) = 1 clock_gettime(CLOCK_MONOTONIC, {951633, 407127379}) = 0 read(103, "GET /socket.io/1/xhr-polling/140"..., 65536) = 447 futex(0xfe49538, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1335429186, 880145}, NULL) = 0 gettimeofday({1335429186, 880691}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {951633, 409303379}) = 0 epoll_wait(4, {}, 64, 164) = 0 clock_gettime(CLOCK_MONOTONIC, {951633, 573509379}) = 0 gettimeofday({1335429187, 45141}, NULL) = 0 futex(0xfe49538, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1335429187, 45282}, NULL) = 0 gettimeofday({1335429187, 45597}, NULL) = 0 write(121, "1a\r\n<script>_(\"2::\");</script>\r\n", 32) = 32 gettimeofday({1335429187, 46077}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {951633, 574638379}) = 0 epoll_wait(4, {{EPOLLIN, {u32=61, u64=382252089405}}}, 64, 522) = 1 clock_gettime(CLOCK_MONOTONIC, {951633, 577418379}) = 0 read(61, "POST /socket.io/1/htmlfile/13930"..., 65536) = 692 futex(0xfe49538, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1335429187, 51165}, NULL) = 0 gettimeofday({1335429187, 52647}, NULL) = 0 write(61, "HTTP/1.1 200 OK\r\nContent-Length:"..., 63) = 63 gettimeofday({1335429187, 54234}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {951633, 583258379}) = 0 epoll_wait(4, {{EPOLLIN, {u32=123, u64=721554505851}}}, 64, 514) = 1 clock_gettime(CLOCK_MONOTONIC, {951633, 603354379}) = 0 read(123, "POST /socket.io/1/htmlfile/46598"..., 65536) = 422 futex(0xfe49538, FUTEX_WAKE_PRIVATE, 1) = 1 gettimeofday({1335429187, 77500}, NULL) = 0 gettimeofday({1335429187, 78477}, NULL) = 0 write(123, "HTTP/1.1 200 OK\r\nContent-Length:"..., 63) = 63 gettimeofday({1335429187, 79913}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {951633, 608929379}) = 0 epoll_wait(4, <unfinished ...> ---------------------- 見ても理解できなかったので、調べてみようと思います。

a-kuma3さんのコメント
C言語を知ってると、プログラムで呼びだしてるシステムコールのままなんですけど、それより上位のレベルで見ると、よく分かんないですよね。 ネットワークのサーバサイドのプログラムなので、 +待って (wait)、 +読んで (read)、 +書いて (write) の繰り返しです。 その間に、時刻を取る処理とか、プロセス間の同期を取る処理が割りこんでます。 タイムスタンプをつける -tt とか、strace のオプションに入れときゃ良かったですね(すんません)。 http://www.netadmintools.com/html/1strace.man.html

araishiさんのコメント
ご回答ありがとうございます。 はてなで質問していると次々とわからないことがでてきて、 自分の未熟さがわかります。精進します。
関連質問

●質問をもっと探す●



0.人力検索はてなトップ
8.このページを友達に紹介
9.このページの先頭へ
対応機種一覧
お問い合わせ
ヘルプ/お知らせ
ログイン
無料ユーザー登録
はてなトップ