straceはユーザーランドアプリケーションの挙動の確認やデバッグに使える便利なツールです。どのシステムコールが、どのような引数で呼び出され、その結果どうなったのかをログとして残せます。不可解な挙動をするプログラムを調べる上で覚えておくと損はないツールです。今回はstraceの基本的な使い方に加えて、わざとシステムコールをエラー終了させる、エラーインジェクションについても紹介しましょう。
不可解なプログラムについて
この世にあるソフトウェアはすべて何らかの不具合を抱えています。もし不具合のないソフトウェアが存在するとしたら、その事実自体が不具合と言えるかもしれません。そのまま放置しておくと、きっと将来なにがしかの不具合が顕現することでしょう。よってソフトウェアエンジニアと呼ばれる人たちは、日々ソフトウェア様のご機嫌を伺い、こびりついた不具合を削ぎ落とし、場合によってはあえて不具合を埋め込みながら生活しているのです。
そんなわけで目の前で動いているアプリケーションやシステムは、たくさんのエンジニアによる多大な貢献と、ソフトウェア様のご機嫌によって成り立っているということを、心の片隅にでもとどめておいてください[1][2]。
初っ端から脇道にそれてしまいましたが、straceの話に戻りましょう。一般的にプログラムが意図しない挙動を見せた時は、さまざまな方法で原因を追求します。たとでばデバッガを使って実際の動作を追跡したり、ソースコードから挙動を読み解いたり、デバッグ用の出力を追加してトライアンドエラーを繰り返したり、毛むくじゃらのクマに話しかけたりとその方法は様々です。
Linuxの場合は、デバッグ時にstraceを使うと、次のような利点が得られます。
- プログラムそのものに手を加える必要はない
- ソースコードがなくてもある程度追跡可能
- システムコールの実行の流れを把握できる
- システムコール呼び出しの性能・
統計情報が得られる - システムコールの戻り値を書き換えられる
- 使うための準備がかんたん
「システムコール」
- 設定ファイルをどの順番で読み込んでいるか
- メッセージ表示周辺のシステムコールの引数や戻り値はどうなっているのか
- そもそもデータを送信しようとしているのか
- どこかでタイムアウトやリトライが発生していないか
- どのシステムコールの呼び出し周辺で時間がかかっているのか
また、straceは次のような調査には向いていません。
- 特定の処理に対してデバッグログを追加したい
- システムコール以外の関数の呼び出しや回数を確認したい
- ソースコードの処理内容を変えたい
- CPUのレジスタを確認したい
- カーネルそのものをデバッグしたい
これらを実施したいのであればgdbやperf、eBPFといった他のツールや仕組みを使うことになるでしょう。
深夜はstraceするに限る
さて、実際にstraceを使ってみましょう。今回はUbuntu 22.
$ sudo apt install strace
試しに適当なプログラムを実行してみましょう。この場合、
$ strace cat /etc/lsb-release execve("/usr/bin/cat", ["cat", "/etc/lsb-release"], 0x7ffdac1fde48 /* 82 vars */) = 0 (中略) openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=104, ...}, AT_EMPTY_PATH) = 0 fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0 (中略) read(3, "DISTRIB_ID=Ubuntu\nDISTRIB_RELEAS"..., 131072) = 104 write(1, "DISTRIB_ID=Ubuntu\nDISTRIB_RELEAS"..., 104DISTRIB_ID=Ubuntu DISTRIB_RELEASE=22.04 DISTRIB_CODENAME=jammy DISTRIB_DESCRIPTION="Ubuntu 22.04.2 LTS" ) = 104 read(3, "", 131072) = 0 munmap(0x7f3a0dea8000, 139264) = 0 close(3) = 0 close(1) = 0 close(2) = 0 exit_group(0) = ? +++ exited with 0 +++
まず、execve()
で実際に呼び出すプログラムを実行しています。その後、catを実行する際にさまざまなライブラリをロードする処理が走ったあとに/etc/
」openat()
で開いています。その戻り値であるread()
で読み込み、その後に標準出力write()
しています。straceはトレース結果を標準エラー出力に出力しているため、catの実行結果と混ざって表示されています。最後に各種fdを閉じて、exit_
して終了という流れです。
上記はシンプルな結果ですが、これだけでも使えることがわかるでしょう。たとえば
表示するシステムコールを限定する
特定のシステムコールだけに限定したいなら-e システムコール名
」openat()
とread()
だけに限定したいなら次のように指定します。
$ strace -e openat,read cat /etc/lsb-release openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\237\2\0\0\0\0\0"..., 832) = 832 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 read(3, "DISTRIB_ID=Ubuntu\nDISTRIB_RELEAS"..., 131072) = 104 DISTRIB_ID=Ubuntu DISTRIB_RELEASE=22.04 DISTRIB_CODENAME=jammy DISTRIB_DESCRIPTION="Ubuntu 22.04.2 LTS" read(3, "", 131072) = 0 +++ exited with 0 +++
この-e システムコール
」-e trace=システムコール
」-e
」
- 「
-e '!openat,read'
」:openat()
とread()
以外 - 「
-e %file
」:ファイル操作系のシステムコール一式のみ表示 - 「
-e %process
」:exec()
やexit()
などのプロセス系のシステムコール一式のみ表示 - 「
-e %network
」:ネットワーク系のシステムコール一式のみ表示 - 「
-e signal=SIGUSR1
」:SIGUSR1シグナルの発生のみを表示
なお最初のケースで!
」
出力先を変更する
straceは何もしないと標準エラー出力に出力します。よってstrace FOO 2> debug.
」
straceの結果だけを保存したいのであれば、-o FILE
」
$ strace -o debug.log cat /etc/lsb-release
これであとからじっくり実行結果を確認できます。
出力結果にタイムスタンプを付ける
出力結果にはタイムスタンプがあると便利です。straceにはいくつかのタイムスタンプのオプションが存在します。
-t
:時計の時刻を秒単位で表示(例: 22:39:13 read...
)-tt
:時計の時刻をマイクロ秒単位で表示(例: 22:39:44.
)314041 read... -ttt
:Unix時間をマイクロ秒単位で表示(例: 1683553208.
)654890 read...
「--timestamp=time:ns
」-T
」
22:41:50.730704 read(3, "DISTRIB_ID=Ubuntu\nDISTRIB_RELEAS"..., 131072) = 104 <0.000033>
上記の例だと、行末の0.
」read()
にかかった時間です
ターゲットから起動したプロセスも調査対象に入れる
あるプログラムが別のプログラムを起動することもよくあります。この場合、straceが調べるのはstraceの引数に渡したプログラムだけです。たとえばshコマンド経由でcatを呼び出してみましょう。
$ strace -e openat,read,execve,%process sh -c "cat /etc/lsb-release" execve("/usr/bin/sh", ["sh", "-c", "cat /etc/lsb-release"], 0x7ffd05f72500 /* 82 vars */) = 0 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\237\2\0\0\0\0\0"..., 832) = 832 vfork() = 2871878 wait4(-1, DISTRIB_ID=Ubuntu DISTRIB_RELEASE=22.04 DISTRIB_CODENAME=jammy DISTRIB_DESCRIPTION="Ubuntu 22.04.2 LTS" [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 2871878 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=2871878, si_uid=1000, si_status=0, si_utime=0, si_stime=0} --- wait4(-1, 0x7ffe7b65f9ec, WNOHANG, NULL) = -1 ECHILD (子プロセスがありません) exit_group(0) = ? +++ exited with 0 +++
「/etc/
」vfork()
」wait4()
」
「-f
」
$ strace -f -e openat,read,execve,%process sh -c "cat /etc/lsb-release" execve("/usr/bin/sh", ["sh", "-c", "cat /etc/lsb-release"], 0x7fffd5dfea38 /* 82 vars */) = 0 (中略) vfork(strace: Process 2873473 attached <unfinished ...> [pid 2873473] execve("/usr/bin/cat", ["cat", "/etc/lsb-release"], 0x556212d323f8 /* 82 vars */ <unfinished ...> (中略) [pid 2873473] openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 [pid 2873473] read(3, "DISTRIB_ID=Ubuntu\nDISTRIB_RELEAS"..., 131072) = 104
今度はshコマンドだけでなく、そこから起動したcatコマンドも追跡してくれました。これはマルチスレッドなプログラムを検査したい場合にも有効です。
ちなみに-Y
」
$ strace -Y -ff -e openat,read,execve,%process sh -c "cat /etc/lsb-release" execve("/usr/bin/sh", ["sh", "-c", "cat /etc/lsb-release"], 0x7fff3a037350 /* 82 vars */) = 0 (中略) [pid 2876104<sh>] execve("/usr/bin/cat", ["cat", "/etc/lsb-release"], 0x55b1b8dcd3f8 /* 82 vars */ <unfinished ...> (中略) [pid 2876104<cat>] openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3
「-o ファイル名
」-ff
」元のファイル名.PID
」
ファイル名、構造体や文字列の展開
「-yy
」
$ strace -yy -e openat,read cat /etc/lsb-release (中略) openat(AT_FDCWD</home/shibata>, "/etc/lsb-release", O_RDONLY) = 3</etc/lsb-release> read(3</etc/lsb-release>, "DISTRIB_ID=Ubuntu\nDISTRIB_RELEAS"..., 131072) = 104
「-v
」
$ strace -yy -v -e newfstatat cat /etc/lsb-release (中略) newfstatat(3</etc/lsb-release>, "", {st_dev=makedev(0x103, 0x2), st_ino=1840137, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=8, st_size=104, st_atime=1683550922 /* 2023-05-08T22:02:02.942255967+0900 */, st_atime_nsec=942255967, st_mtime=1676563352 /* 2023-02-17T01:02:32+0900 */, st_mtime_nsec=0, st_ctime=1676700937 /* 2023-02-18T15:15:37.548645620+0900 */, st_ctime_nsec=548645620}, AT_EMPTY_PATH) = 0
この-v
」-e abbrev=none
」-e 'abbrev=!foo,bar'
」!
」
straceは自動で文字列を32文字までは展開してくれますが、この文字数は-s 文字数
」-x
」-xx
」
通常の表示:八進数表記となる openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\237\2\0\0\0\0\0"..., 832) = 832 「-x」付き:ASCII文字以外も含まれる文字列は十六進数表記となる openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 read(3, "\x7f\x45\x4c\x46\x02\x01\x01\x03\x00\x00\x00\x00\x00\x00\x00\x00\x03\x00\x3e\x00\x01\x00\x00\x00\x50\x9f\x02\x00\x00\x00\x00\x00"..., 832) = 832 「-xx」付き:ASCII文字が含まれるかどうかに関係なく十六進数表記となる openat(AT_FDCWD, "\x2f\x6c\x69\x62\x2f\x78\x38\x36\x5f\x36\x34\x2d\x6c\x69\x6e\x75\x78\x2d\x67\x6e\x75\x2f\x6c\x69\x62\x63\x2e\x73\x6f\x2e\x36", O_RDONLY|O_CLOEXEC) = 3 read(3, "\x7f\x45\x4c\x46\x02\x01\x01\x03\x00\x00\x00\x00\x00\x00\x00\x00\x03\x00\x3e\x00\x01\x00\x00\x00\x50\x9f\x02\x00\x00\x00\x00\x00"..., 832) = 832
情報の表示オプションについてまとめるとstrace -fvttTyyY -o ファイル名
」
さらに工夫せるstrace
定番の表示オプション以外にも、組み合わせたり単体で使うと便利なオプションがいくつか存在します。
特定のファイル関連の処理のみ表示する
「-P ファイル
」
$ strace -P /etc/lsb-release cat /etc/lsb-release openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=104, ...}, AT_EMPTY_PATH) = 0 fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0 read(3, "DISTRIB_ID=Ubuntu\nDISTRIB_RELEAS"..., 131072) = 104 DISTRIB_ID=Ubuntu DISTRIB_RELEASE=22.04 DISTRIB_CODENAME=jammy DISTRIB_DESCRIPTION="Ubuntu 22.04.2 LTS" read(3, "", 131072) = 0 close(3) = 0 +++ exited with 0 +++
ここでは-P
」
実行中のプロセスをチェックする
ここまではプログラムの起動時にstraceを実行する方法でした。-p
」
$ strace -p <pid>,<pid>,...
複数のプロセスの指定が可能です。Ctrl-Cを入力することで、straceによる調査を終了します。
統計情報の表示
「-c
」
$ strace -c cat /etc/lsb-release DISTRIB_ID=Ubuntu DISTRIB_RELEASE=22.04 DISTRIB_CODENAME=jammy DISTRIB_DESCRIPTION="Ubuntu 22.04.2 LTS" % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 20.46 0.000089 8 10 mmap 16.78 0.000073 36 2 munmap 11.72 0.000051 17 3 mprotect 8.97 0.000039 6 6 close 8.97 0.000039 9 4 openat 6.90 0.000030 6 5 newfstatat 5.29 0.000023 7 3 read 4.60 0.000020 20 1 write 4.14 0.000018 6 3 brk 2.30 0.000010 10 1 getrandom 1.84 0.000008 8 1 fadvise64 1.84 0.000008 8 1 prlimit64 1.61 0.000007 3 2 1 arch_prctl 1.61 0.000007 7 1 set_robust_list 1.61 0.000007 7 1 rseq 1.38 0.000006 6 1 set_tid_address 0.00 0.000000 0 4 pread64 0.00 0.000000 0 1 1 access 0.00 0.000000 0 1 execve ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000435 8 51 2 total
「-S ソート対象
」
システムコールよエラーになれ
straceはシステムコールを呼び出すポイントと戻るポイントに対して処理を行います。さらにこのポイントで指定した操作を行うことも可能です。その最たる例がエラーインジェクションでしょう。システムコールが戻るときにエラーを返すようにすることで、プログラムのテストでも難しいエラー系の処理を通すことができます。
システムコールをエラーにする
具体的な例を見ていきましょう。まず単純にこれまでの例でファイルを開いたときにエラーになるようにしてみます。-e fault=システムコール
」openat()
だったのでこれを指定します。
$ strace -e fault=openat cat /etc/lsb-release execve("/usr/bin/cat", ["cat", "/etc/lsb-release"], 0x7fff744bfc88 /* 83 vars */) = 0 brk(NULL) = 0x564ef3b4d000 arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc78c33370) = -1 EINVAL (無効な引数です) mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0b4cad9000 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (そのようなファイルやディレクトリはありません) openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = -1 ENOSYS (関数は実装されていません) (INJECTED)
実はopenat()
はライブラリのロードでも使われているため、catコマンドの最初のほうでエラーになってしまいます。今回は/etc/
」-P /etc/
」
$ strace -P /etc/lsb-release -e fault=openat cat /etc/lsb-release openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = -1 ENOSYS (関数は実装されていません) (INJECTED) cat: /etc/lsb-release: 関数は実装されていません +++ exited with 1 +++
うまくエラーになりましたね。
エラー番号を変更する
先ほどまでのエラーは戻り値がerror=エラー名
」
$ strace -P /etc/lsb-release -e fault=openat:error=EINVAL cat /etc/lsb-release openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = -1 EINVAL (無効な引数です) (INJECTED) cat: /etc/lsb-release: 無効な引数です +++ exited with 1 +++
エラー番号については、個々のシステムコールのmanページを見るとわかります。また、moreutilsパッケージのerrnoコマンドを使うとerrno -l
」
エラーのタイミングを調整する
「when=N
」openat()
だけエラーになっています。
$ strace -P /etc/lsb-release -e openat -e fault=openat:error=EINVAL:when=2 cat /etc/lsb-release{,}{,} >/dev/null openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = -1 EINVAL (無効な引数です) (INJECTED) cat: /etc/lsb-release: 無効な引数です openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 +++ exited with 1 +++
このwhen=
」first[..
」
when=M+
:M回目以降をすべてエラーにするwhen=M..
:M回目からN回目までをエラーにするN when=M+S
:M回目からS回ごとにエラーにする(= 「M + S x n」 回目をエラーにする) when=M..
:M回目からN回目までのうち、M回目からS回ごとにエラーにするN+S
システムコールの戻り値を置き換える
ここまで利用した-e fault=
」-e inject=
」-e inject=
」retval=
」
$ strace -P /etc/lsb-release -e openat -e inject=openat:retval=-2 cat /etc/lsb-release strace: Inadvertent injection of error 2 is possible for retval=18446744073709551614 openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = -2 (INJECTED) cat: /etc/lsb-release: そのようなファイルやディレクトリはありません +++ exited with 1 +++
openat()
の場合は、APIの使用上
シグナルを発生させる
「signal=シグナル
」
$ strace -P /etc/lsb-release -e openat -e inject=openat:signal=INT cat /etc/lsb-release openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} --- +++ killed by SIGINT +++
遅延時間を挿入する
「delay_
」delay_
」
$ strace -tt -P /etc/lsb-release -e openat -e inject=openat:delay_enter=1s:delay_exit=2s cat /etc/lsb-release >/dev/null 00:55:20.180126 openat(AT_FDCWD, "/etc/lsb-release", O_RDONLY) = 3 (DELAYED) 00:55:23.182622 +++ exited with 0 +++
時刻のサフィックスは
このように、straceのエラーインジェクション機能を使うと、様々なタイミングで任意のエラーを発生させられます。システムコールが想定外のエラーを返した時にソフトウェア様がへそを曲げてしまわないためにも、きちんとエラー処理を書いておいて、テストすることを心がけましょう。