straceを使ったデバッグ
ここで、デバッグツールの登場だ。私にとってなくてはならないツールの1つが、straceだ。straceはシステムコールトレーサで、すでに実行されているプログラムによって発せられたコールを追跡する(straceを既存のPIDにバインドする)ことも、テストしたいプロセスをstraceに開始させることもできる。
では、straceの使い方を実例とともに見ていくことにしよう。
KDE起動時の問題
以前、私はKDEを起動する際の問題をデバッグしていた。返されたエラーメッセージからは、何の手がかりも得ることができなかった。
_KDE_IceTransSocketCreateListener: failed to bind listener _KDE_IceTransSocketUNIXCreateListener: ...SocketCreateListener() failed _KDE_IceTransMakeAllCOTSServerListeners: failed to create listener for local Cannot establish any listening sockets DCOPServer self-test failed.
これは、私にとってはあまり役立つものではなかった。このメッセージから読み取ることができたのは、プロセス間のコミュニケーションに使われる重要なKDEプログラムであるdcopserverが開始できなかったということと、このエラーがICE(Inter Client Exchange)プロトコル(XFree86の一部)と関連しているということだけだった。何が問題の原因となったのかがさっぱりわからず、私は途方にくれていた。
そこで私はstraceを使ってdcopserverを実行し、dcopserverが起動しようとしたときに何が起きているのか、舞台裏を見てみることにした。
strace -f -F -o ~/dcop-strace.txt dcopserver
-f -F
オプションは、それぞれfork(2)とvfork(2)プロセス(もしあれば)もトレースするようstraceに指示するものだ。-o
オプションは、straceからの出力をすべてdcop-strace.txtファイルに保存するよう指定する。dcopserver
はstraceが実行してトレースする対象のプログラムだ。
再びエラーが起きた後、dcop-strace.txtファイルを見てみると、システムコールを含め、数多くの情報が残されているのがわかった。エラーに関連があるのは、エラーの直前に発生しているシステムコールだ。
27207 mkdir("/tmp/.ICE-unix", 0777) = -1 EEXIST (File exists) 27207 lstat64("/tmp/.ICE-unix", {st_mode=S_IFDIR|S_ISVTX|0755, st_size=4096, ...}) = 0 27207 unlink("/tmp/.ICE-unix/dcop27207-1066844596") = -1 ENOENT (No such file or directory) 27207 bind(3, {sin_family=AF_UNIX, path="/tmp/.ICE-unix/dcop27207-1066844596"}, 38) = -1 EACCES (Permission denied) 27207 write(2, "_KDE_IceTrans", 13) = 13 27207 write(2, "SocketCreateListener: failed to "..., 46) = 46 27207 close(3) = 0 27207 write(2, "_KDE_IceTrans", 13) = 13 27207 write(2, "SocketUNIXCreateListener: ...Soc"..., 59) = 59 27207 umask(0) = 0 27207 write(2, "_KDE_IceTrans", 13) = 13 27207 write(2, "MakeAllCOTSServerListeners: fail"..., 64) = 64 27207 write(2, "Cannot establish any listening s"..., 39) = 39
1行目からは、モード0777で/tmp/.ICE-unixディレクトリを作ろうとしているプロセスがあったことがわかる。この試みは、ディレクトリがすでに存在しているために失敗している。2番目のコール(lstat64)は、そのディレクトリのステータスを取得し、モードが0755であることを示している。これは、問題解決への最初の手がかりだ。つまり、システムコールはモード0777でディレクトリを作成しようとしているにもかかわらず、すでに存在するディレクトリのモードは0755であるからだ。3番目のコール(unlink)は、あるファイルを削除しようとしているが、そのファイルは存在しない。これは特にエラーと関連はない。存在する可能性がある古いファイルを削除しようとしているだけだ。
4行目で、私の疑いは確信に変わった。ここでは、/tmp/.ICE-unix/dcop27207-1066844596にbindしようとして、permission deniedエラーにより失敗している。.ICE-unixディレクトリの所有者はrootでグループはroot、書き込み権限を持つのは所有者だけだ。root以外のユーザはこのディレクトリにファイルを作成することはできない。このパーミッションが0777にセットされていれば、この操作は成功して、mkdirコマンドは目的を果たすことができたはずだ。
そこで、chmod 0777 /tmp/.ICE-unix
を実行してから、再度KDEを開始してみると、今回は正常に開始された。問題は解決したのだ。straceを実行してその出力ファイルを分析するのには、たった数分しかかからなかった。
注:chmod 0777
の実行はあくまでもテスト目的である。私は、スティッキービットのセットされていないディレクトリをworld-writableにすることには賛成できない。スティッキービットをディレクトリにセットすると、そのディレクトリがworld-writableであるかどうかにかかわらず、ユーザは他のユーザのファイルを削除できなくなる。/tmpディレクトリによくスティッキービットがセットされているのは、この目的のためだ。KDEが正常に機能するようになってから、私はchmod
+t /tmp/.ICE-unix
を実行してスティッキービットをセットした。
ライブラリ関連の問題
straceのもう1つの利用法は、ライブラリに関連する問題を解決することだ。プログラムでldd
を実行すると、そのプログラムが使用しているライブラリと、そのライブラリの場所を教えてくれる。しかし、システムで使用しているGlibcのバージョンが古い(バージョン2.2以前)場合、ldd
プログラムにバグがあるので注意してほしい。このバージョンのldd
では、あるディレクトリにライブラリがあると報告されても、実際にプログラムを実行してみると、ダイナミックリンカ(/etc/ld-linux.so.2)が別の場所にライブラリを見つけるという問題がある。これは通常、/etc/ld.so.confと/etc/ld.so.cacheが同期していないか、/etc/ld.so.cacheファイルが破損していることが原因となって起きる。私のGlibc-2.3.2システムではこれを再現できないところを見ると、このバグはすでに解決されているようだ。
さらにldd
は、プログラムが利用するライブラリをすべては表示しない。dlopen(3)システムコールは、オンデマンドでダイナミックライブラリをロードできるが、これらのライブラリはldd
の出力には現れない。Glibcの一部であるName Service Switch(NSS)ライブラリはこの良い例だ。NSSの仕事の1つは、システムのパスワードデータベースの場所をアプリケーションに伝えることだ。NSSライブラリは、アプリケーションから直接リンクされることはなく、Glibc自身がこのdlopenシステムコールを使って配置する。万が一これらのライブラリの場所がわからなくなってしまうと、その事実は報告されないまま、アプリケーションはユーザIDをユーザ名に解決するなどの処理ができなくなってしまう。これを再現してみよう。
whoami
プログラムは自分のユーザ名を確認するためのものである。これは、実行しているユーザのユーザ名を知る必要のあるスクリプトで実行すると便利だ。whoamiの出力のサンプルを次に示す。
# whoami
root
ここで、Glibcのアップグレード中に何か問題があり、ユーザIDとユーザ名のマッピングに必要なNSSライブラリが見つからないと仮定しよう。これをシミュレートするには、/lib/libnss_files.so.2シンボリックリンクの名前を変更するなどして一時的に見つからないようにすればよい。
# mv /lib/libnss_files.so.2 /lib/libnss_files.so.2.backup whoami whoami: cannot find username for UID 0
問題が起きているのがわかる。ユーザIDはユーザ名に解決されず、whoami
からの出力には、ライブラリに問題があることを判断する手段はない。ldd
からの出力にも、有力な手がかりは何もない。
# ldd /usr/bin/whoami libc.so.6 => /lib/libc.so.6 (0x4001f000) /lib/ld-linux.so.2 => /lib/ld-linux.so.2 (0x40000000)
この出力からわかるのは、whoami
を実行するにはlibc.so.6とld-linux.so.2が必要であるということだけだ。正常な動作に必要な、その他のライブラリについては何も触れられていない。
ここで、再びstraceに登場願おう。次のコマンドを実行して、whoami
の出力をstraceしてみよう。
strace -o whoami-strace.txt whoami
whoami-strace.txtファイルを見てみると、さまざまなディレクトリでlibnss_files.so.2ファイルを探そうとするコールが発生しているが、いずれも失敗に終わっていることがわかる。
open("/lib/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory) open("/lib/i686/mmx/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory) stat64("/lib/i686/mmx", 0xbffff190) = -1 ENOENT (No such file or directory) open("/lib/i686/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory) stat64("/lib/i686", 0xbffff190) = -1 ENOENT (No such file or directory) open("/lib/mmx/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory) stat64("/lib/mmx", 0xbffff190) = -1 ENOENT (No such file or directory) open("/lib/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory) stat64("/lib", {st_mode=S_IFDIR|0755, st_size=2352, ...}) = 0 open("/usr/lib/i686/mmx/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory) stat64("/usr/lib/i686/mmx", 0xbffff190) = -1 ENOENT (No such file or directory) open("/usr/lib/i686/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
straceのようなプログラムがなかったら、ライブラリが欠けていることはわからなかっただろう。straceは少なくとも、問題解決への糸口を提供してくれる。ここでは、libnss_files.so.2がどこにいってしまったのかを調べ、元の場所に戻してやればよい。
特定のシステムコールだけをトレースする
何を調べるかがはっきりしている場合は、特定の種類のコールだけを表示するようstraceに指示することもできる。たとえば、configureスクリプトによって実行されたプログラムのリストが欲しい場合には、execveシステムコールを調べればよい。このコールだけを表示するようstraceに指示するには、次のコマンドを実行する。
strace -f -o configure-strace.txt -e execve ./configure
出力は次のようになるはずだ。
2720 execve("/usr/bin/expr", ["expr", "a", ":", "\\(a\\)"], [/* 31 vars */]) = 0 2725 execve("/bin/basename", ["basename", "./configure"], [/* 31 vars */]) = 0 2726 execve("/bin/chmod", ["chmod", "+x", "conftest.sh"], [/* 31 vars */]) = 0 2729 execve("/bin/rm", ["rm", "-f", "conftest.sh"], [/* 31 vars */]) = 0 2731 execve("/usr/bin/expr", ["expr", "99", "+", "1"], [/* 31 vars */]) = 0 2736 execve("/bin/ln", ["ln", "-s", "conf2693.file", "conf2693"], [/* 31 vars */]) = 0
これでわかるとおり、straceはプログラマはもちろん、一般のユーザにも非常に役に立つツールだ。確かに、出力は少々わかりづらいが、ほとんどの人にはかかわりのない出力(メモリアロケーションコールなど)も多い。出力の中から、permission deniedエラー、no such file or directoryエラーなど、必要な情報だけを選び出すようにすればよいだろう。