サービス直前の非常事態！ アプリケーションが復帰しない？：Linuxトラブルシューティング探偵団（2）（2/3 ページ）

[高田哲生，NTT OSSセンタ]

スタックトレースで停止個所を突き止めろ！

　状況から見ると、どうやらアプリケーションが悪いわけではなさそうです。ここからはいよいよ、ソフトウェアの下位レイヤであるOS部分の解析に入ります。LinuxのオープンソースOSたる長所を生かして、ソースコードを読みつつ解析していくことになりそうです。

　……とはいえ、OS以下のレイヤをある程度分類し、事前に要因を想定しておかなければ、やみくもにソースコードを読むことになってしまいます。

　「アプリケーションは悪くない」ことを前提とすると、残りのレイヤは以下の3つに絞られます。

1. ライブラリ（glibcなど）
2. カーネル
3. ハードウェア

　まず1と2を切り分けるために、「マジックSysRqキー」（以下、SysRqキー）でスタックトレースを取得してみましょう。

　ではここから、実際にスタックトレースを出力するための手順を紹介します。

1. SysRqが有効かどうかを確認

　まずは現在のサーバで、SysRqキーが有効になっているかどうかを以下のようにして確かめます。kernel.sysrqが0になっている場合は無効になっています。

# sysctl -a | grep sysrq kernel.sysrq = 0

2. sysctlコマンドでSysRqキーを有効にする

# sysctl -w kernel.sysrq=1 kernel.sysrq = 1

3. 実際にSysRqキーを試してみる

　SysRqキーは基本的に、サーバに直接接続されているコンソール上で実行しますので、まずはそこまで移動しましょう。CUIの場合（ランレベルが3など）は問題ありませんが、GUIを利用している（ランレベルが5）場合は、［Ctrl］＋［Alt］＋［F1］などで端末に切り替えましょう。

　端末に移動した状態で、［Alt］＋［SysRq］＋hとキーボードを押してみてください。以下のように出力されるはずです。

SysRq : HELP : loglevel0-8 reBoot Crash tErm kIll saK showMem powerOff showPc unRaw Sync showTasks Unmount shoWcpus

　これは、SysRqキーで実行できるコマンド群を示しています。SysRqキーと大文字部分のキーを組み合わせて押すことで、コマンドが実行できます。

4.スタックトレースを出力する

　いよいよスタックトレースを取得します。3.で出力されていたコマンド群のうち、「showTasks」というのが全プロセスのスタックトレースを出力するコマンドです。まず「つかまえたい事象が起こっている」のを確認したうえで、［Alt］＋［Sys Rq］＋Tと押してみます。これで、全プロセスのスタックトレースが出力されたはずです。

　この出力は、RHELの場合はデフォルトで/var/log/messageにも出力されます。ここからお望みのプロセスを探し出せば、現在どこで処理が止まっているかが分かります。

　例えば、今回の対象プログラム名が「test」だった場合のスタックトレースは、以下のような出力になります。

1:test S 0000000000000000 0 19127 18965 (NOTLB) 2: 0000010020179b18 0000000000000006 0000010022997750 0000000000000074 3: 0000000000000000 0000000000000000 0000010001013a80 000000003d6cfb88 4: 000001003c998030 000000000000f4c9 5:Call Trace:<ffffffff80132645>{recalc_task_prio+337} <ffffffff8030c730>{schedule_timeout+224} 6: <ffffffff80135bbc>{prepare_to_wait_exclusive+21} <ffffffff802ae531>{skb_recv_datagram+373} 7: <ffffffff80135c64>{autoremove_wake_function+0} <ffffffff80135c64>{autoremove_wake_function+0} 8: <ffffffff802eaf98>{udp_recvmsg+118} <ffffffff802abf5e>{sock_common_recvmsg+48} 9: <ffffffff8030bc9d>{thread_return+0} <ffffffff802a8a70>{sock_recvmsg+284} 10: <ffffffff8022e864>{pty_write+290} <ffffffff80135b18>{remove_wait_queue+16} 11: <ffffffff80135c64>{autoremove_wake_function+0} <ffffffff802a8673>{sockfd_lookup+16} 12: <ffffffff802a9e9f>{sys_recvfrom+182} <ffffffff80227ac4>{tty_ldisc_deref+103} 13: <ffffffff802281eb>{tty_write+702} <ffffffff8022d5f9>{write_chan+0} 14: <ffffffff80193eec>{dnotify_parent+34} <ffffffff8011026a>{system_call+126}

　スタックトレースの細かい読み方についてはここでは割愛しますが、12行目の赤字部分に注目してください。

　sys_recvfromというのは、カーネル内にあるrecvfrom()の実体です。sys_recvfrom+182というのは、sys_recvfromの途中で止まっていることを示しています。何度か取得してみても同じ結果ですので、recvfrom()の処理のうち、カーネル内の処理でシステムが止まっていると判断できそうです。

関連記事

シェルを使わずにシステムをシャットダウンするには
http://www.atmarkit.co.jp/flinux/rensai/linuxtips/557sysrqsd.html

カーネル内で止まる原因をつかむには？

　スタックトレースを見ることにより、カーネルのrecvfrom()内で処理が停止していることが分かりました。

　次に、カーネルとハードウェアの切り分けに入ります。取得したスタックトレースを参考にカーネルのソースコードを調査してみると、どうやらrecvfrom()の処理ルーチンのうち、UDPのパケットを待ち受ける処理の途中で止まってしまうようです。

　ところがアプリケーションの作りとしては、select()でパケットが到着したことを確認したうえでrecvfrom()を発行しています。本来ならば、パケットの待ち受け処理で止まるはずがありません。

　しかし、このような処理になるケースが1つだけ考えられます。

　recvfrom()は、その延長上でパケットのチェックサムを調べる（注3）仕組みになっています。ここでエラーが発生すると、パケットを破棄したうえで次のパケットを待ち受けるという処理に入ってしまうのです（注4）

　今回の実装では、パケット受信処理は以下のように進みます。

1. アプリケーションがソケットを作成し、通信を開始する
2. 作成したソケットをselect()で監視する
3. OS（カーネル）がパケットを受信する
4. select()が復帰する
5. FD_ISSET()で、各ソケットが読み込み可能であるかどうか確かめる
6. 5で読み込み可能だったソケットに対してrecvfrom()で受信処理を行う
7. 2に戻る

　6のrecvfrom()による受信処理は、単一のソケットに対して行われます。もしこの処理中にチェックサムエラーが出ると、当該ソケットに対するパケットを待ち受けることになってしまい、ほかのソケットに対する受信処理ができなくなってしまいます。

　どうやら、これは今回の状況とかなり符合しそうです。この事象の原因はサーバではなくクライアント、それもハードウェアに問題がある可能性が出てきたということになります。

　次に、パケットのチェックサムエラーが発生しているかどうかを調べる必要がありますが、それに関しては簡単な方法があります。Linuxは、SNMPアプリケーションのために/proc/net/snmpというエントリを用意しています。この中にある「InErrors」という値が、まさにこのチェックサムエラーが出た数を示しています。

　この値を顧客に調べてもらったところ、やはりチェックサムエラーがカウントされているとのこと。従って、端末から不正なパケットが送られてきたことが、今回の事象のきっかけとなったことに間違いなさそうです。

　顧客によると、その後の追加調査で、ある特定の端末が、とある時点を境に、エラーパケットしか送信しなくなるということが分かりました。しかも、この端末はリセットすると正常な状態に戻るため、それが再現条件を特定するのが難しい一因となっていたようです。

注3：チェックサムについては、http://www.atmarkit.co.jp/fwin2k/network/baswinlan010/baswinlan010_02.htmlを参考にしてください

注4：最近のNICの中には、受信時にハードウェアレベルでチェックサムを検査してくれるものもあるので、それを利用している場合には発生しません