第14回「 SystemTap ノススメ」
Tweet
今回は、カーネルに関するトラブル解析で大活躍する SystemTap についてです。SystemTap の使用を容認できるかどうかが問題事象の原因を究明できるかどうかに直結しそうな、切り札と言えるくらいに重要なツールです。導入手順と使い方については Red Hat 社のウェブサイトにある記事（ https://access.redhat.com/ja/node/882873 ）を参照していただくとして、ここでは実際の調査で使用できるサンプルを紹介したいと思います。
サンプル1：再起動要求をカーネルパニックに置き換える。
正常なシャットダウンシーケンスを伴わずにシステムが突然再起動するというのは、シリアルコンソールや netconsole を使ってカーネルメッセージの有無を確認することくらいしかできない、システム管理者にとって悩ましいトラブルです。しかし、SystemTap を容認できる場合には、予期せぬ再起動要求をカーネルパニックに置き換えてしまうことで kdump を取得し、誰が再起動要求を発行しているのか、なぜ再起動要求を発行するに至ったのかを調査することができるようになります。（ただし、stonithやトリプルフォールトなど置き換えできない再起動要求もあります）
---------- reboot2panic.stp ここから ----------
function call_panic() %{ panic("Calling panic() due to machine restart\n"); %}
probe kernel.function("machine_emergency_restart") { call_panic(); }
probe kernel.function("machine_restart") { call_panic(); }
---------- reboot2panic.stp ここまで ----------
---------- コマンドライン ここから ---------- # stap -p4 -g -m stap_reboot2panic reboot2panic.stp # staprun stap_reboot2panic.ko & ---------- コマンドライン ここまで ----------
正常なシャットダウンシーケンスを伴って再起動する場合にはカーネルパニックに置き換えたくないので、シャットダウンシーケンスに手を加えずに staprun コマンドが自動的に終了するように、（ staprun コマンドの -L オプションや stap コマンドの -Fオプションではなく）シェルの & 指定を用いてバックグラウンドで開始するようにしています。そのため、シャットダウンシーケンス以外から届いたシグナルによりstaprun コマンドが終了してしまう可能性があることに留意する以外に、特別な対処は不要です。
サンプル2：ファイルのオープン要求とプログラムの実行要求を追跡する。
「緊急コラム： bash 脆弱性（ CVE-2014-6271 ）の影響範囲の調査方法について」の「調査方法2： System Call Auditing と独自カーネルモジュールを併用した調査」では、前回紹介した TaskTracker を用いて、 System Call Auditing ログの中にプロセスの実行履歴を記録するようにしていました。そして、「調査方法4： SystemTap で作成したカーネルモジュールを用いた調査」では、SystemTap を用いて、プログラムの実行要求のみをプロセスの実行履歴と一緒に記録していました。今回は、プログラムの実行要求に加えてファイルのオープン要求も記録してみようと思います。
---------- trace_open_exec.stp ここから ----------
global task_domain[32768];
global history_domain;
global history_execve;
global history_read;
global history_write;
probe begin {
printf("Probe start!\n");
}
function get_current:long() {
return task_current() & %{ ULONG_MAX %};
}
function is_success:long(ret:long) {
return ret <= -4096="" ||="" ret="">= 0;
}
function make_domain:string() {
task = get_current();
if (task_domain[task] == "")
task_domain[task] = sprintf("%s(%d)", execname(), pid());
if (history_domain[task_domain[task]] == "")
history_domain[task_domain[task]] = task_domain[task];
return history_domain[task_domain[task]];
}
probe kernel.function("copy_process").return {
if (is_success($return))
task_domain[$return] = make_domain();
}
probe kernel.function("do_execve") {
make_domain();
}
probe kernel.function("do_execve").return {
if (is_success($return)) {
task = get_current();
domain = task_domain[task];
if (domain != "") {
filename = kernel_string($filename);
printf("[%s] execve %s by %s\n", ctime(gettimeofday_s()),
filename, domain);
name = " " . filename . "\n";
if (isinstr(history_execve[domain], name) == 0)
history_execve[domain] .= name;
task_domain[task] .= " " . filename;
history_domain[task_domain[task]] = task_domain[task];
}
}
}
probe kernel.function("do_sys_open").return {
if (is_success($return)) {
domain = make_domain();
filename = user_string($filename);
if (($flags & 3) != 3)
printf("[%s] %s %s by %s\n", ctime(gettimeofday_s()),
($flags & 3) == 0 ? "read" : (($flags & 3) == 1 ? "write" :
"read/write"), filename, domain);
name = " " . filename . "\n";
if (($flags & 3) == 0 || ($flags & 3) == 2)
if (isinstr(history_read[domain], name) == 0)
history_read[domain] .= name;
if (($flags & 3) == 1 || ($flags & 3) == 2)
if (isinstr(history_write[domain], name) == 0)
history_write[domain] .= name;
}
}
probe kernel.function("free_task") {
delete task_domain[$tsk];
}
probe end {
printf("Probe end!\n");
foreach(i in history_domain) {
domain = history_domain[i];
printf("domain: %s\n", domain);
if (history_execve[domain] != "")
printf("execve:\n%s", history_execve[domain]);
if (history_read[domain] != "")
printf("read:\n%s", history_read[domain]);
if (history_write[domain] != "")
printf("write:\n%s", history_write[domain]);
printf("\n");
}
delete history_domain;
delete history_read;
delete history_write;
delete history_execve;
}
---------- trace_open_exec.stp ここまで ----------
---------- コマンドライン ここから ---------- # stap -p4 -g -DMAXSTRINGLEN=4096 -m stap_trace_open_exec trace_open_exec.stp # staprun stap_trace_open_exec.ko ---------- コマンドライン ここまで ----------
staprun を開始すると、リアルタイムにファイルのオープンとプログラムの実行要求が表示されていきます。そして、 Ctrl-C により中断すると、それまでに蓄積された結果が、プロセスの実行履歴単位で出力されるようになっています。
このサンプルは簡単に使えますが、相対パス名などがそのまま記録されてしまうため、要件を満たせない可能性があります。絶対パス名を使って正確に記録したい場合には「調査方法3：独自カーネルモジュール AKARI を用いた調査」をご検討ください。
（半田哲夫）
コーヒーブレーク「サポートにおける環境問題」
不具合の調査や原因解析を行う際に、それをサポートセンターの中で再現できるかどうかは、問題解決の成否を左右する重要な鍵となります。依頼元で発生した事象をサポートセンターの中で再現することができれば、挙動を確認しつつ、ソースコードを解析して調べることができます（対象がオープンソースであれば）。解決に向けたパスポートを手にしたようなものです。
一方、再現ができない場合は、サポートセンターの中では、「問題の所在が確認できていない」状態です。存在していない問題を解くことは誰にもできませんから、サポートセンターではなんとかその問題を再現しようと努力することになります。実際の問い合わせでは、残念ながらこちらのほうが圧倒的に多くなっています。
では、どうして依頼元で発生した問題が、サポートセンターの中で再現しないことが起こるのでしょうか？それについて具体例（いずれも実例があります）を見ると納得いただけると思います。
- データの内容に依存して起こる問題
- 設定ファイル、アプリケーションの起動オプションにより生じる問題
- 使用しているミドルウェアにより生じる問題
- 使用しているソフトウェアの特定バージョンの不具合により生じる問題
- 「時間」に関する要因により生じる問題
- 使用しているハードウェアにより生じる問題
- システムの負荷状態により生じる問題
- クライアントの接続数により生じる問題
- ディスク構成により生じる問題
つまり、依頼元で発生した問題がサポートセンターで再現しない理由は、双方の「環境の差異」にあるわけです。しかも、ややこしいことに依頼元の環境は多くの場合、単一ではありません。開発環境、試験環境、検証環境、移行環境、本番環境（商用環境）など複数の環境が存在するのが普通です。
問合せをする際に意識して欲しいのは、「サポートセンターの技術者は、教えてもらわないと依頼元の環境を確認しようがない」ということです。仮に使用しているミドルウェアや商用製品に起因する不具合の場合、それらを使用していることを教えてもらわなければ、サポートセンターの中でどれほど調査しても答えは見つかりません。環境を正確に説明することの重要性を再認識していただきたいと思います。
（原田季栄）
Tweet