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エラーなど、必要な情報だけを選び出すようにすればよいだろう。