Linuxコマンドをトレースする

今回は、straceコマンドを用いて、Linuxコマンドをトレースしてみる。
straceコマンドによって、プロセスが呼び出すシステムコールをトレースし、その内容を表示することができる。
よって、エラーを表示しないコードの解析に使える。

実行環境

WSL Ubuntu 18.04.4 LTS

使ったコマンド

基本的な使い方
strace [コマンド]
外部ファイルに出力
strace -o [ファイル名] [コマンド]

lsコマンド

lsコマンドをトレースした結果を、ls.txtというファイルに出力する。

 strace -o ls.txt ls

以下で、一部を取り上げて解析してみる。
最初はシステムコール自体を少し細かく見ていく。

1.execve("/bin/ls", ["ls"], 0x7fffddba6920 /* 16 vars */) = 0

まず一行目のシステムコール。
/bin/lsに格納されているファイルが指定されている。

2.brk(NULL)                               = 0x7fffc48b4000

本来、brk()システムコールは、引数にアドレス値をとることによってデータセグメントの最後のアドレスを変更するものだが、NULLを渡すことで、現在のデータセグメントの値を取得することができる。
参考

3.access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
4.access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)

呼び出し元プロセスが、引数に取ったファイルにアクセスできるかどうかを調べる。
ちなみに、引数二つ目はアクセス権を表し、この例だとF_OKはファイルが存在するかどうか、R_OKだとファイルが存在して、かつ読み込みが可能かどうかというモードである。

5.openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

openatは、ファイルのopenをするopenシステムコールと同じ挙動をする。
openatでは、一つ目の引数からの相対パスを探しに行く。
この場合は、AT_FDCWDという特別な値であるため、openシステムコールと同じようにカレントディレクトリからの相対パス名として解釈される。
返り値の3は、ファイルティスクリプタで、プログラムからファイルを操作する際に、操作対象のファイルを識別・同定するために割り当てられる番号である。

6.fstat(3, {st_mode=S_IFREG|0644, st_size=43246, ...}) = 0

fstat() は stat() と同じで、ファイルについての情報を stat が指すバッファー(二つ目の引数)に格納して返す。
fstatは状態を取得するファイルをファイルディスクリプター fd で指定する点が、ファイルをパスで指定するstatとは異なる。
今回は一つ目の引数を見ると、5行目で指定した3のファイルディスクリプタが指定される。
二つ目の引数は、stat構造体のメンバを呼び出しでおり、st_modeはアクセス保護を、st_sizeはバイト単位の全体のサイズを表す。
0が返っているので、成功している。

7.mmap(NULL, 43246, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f82a037b000
8.close(3)                                = 0

mmapでファイルやデバイスをメモリーにマップする。
一つ目の引数である開始アドレスにNULLが指定されているので、カーネルが指定することになる。
そして、マッピングが成功した領域へのポインタが返されたあと、8行目で3のファイルディスクリプタを閉じる。

11.read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20b\0\0\0\0\0\0"..., 832) = 832
12.fstat(3, {st_mode=S_IFREG|0644, st_size=154832, ...}) = 0

少し飛んで11行目。
ファイルディスクリプタ3から、二つ目の引数のbufferへ832バイトのデータを読み込む。
そして12行目でそのバッファに格納する。

13.mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f82a0370000
14.mmap(NULL, 2259152, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f829fdd0000

13行目でマッピングが初期化され、14行目でfd(file descriptor)=3のマッピングを作成している。

15.mprotect(0x7f829fdf5000, 2093056, PROT_NONE) = 0

mprotectシステムコールでは、メモリ領域のアクセス許可を制御する。
ここでは、一つ目の引数であるアドレスから、二つ目の引数の長さ文のメモリに対するアクセスを、三つ目の引数によって拒否している。

ここまでのまとめ

コマンドを実行するためのライブラリの読み込みが行われてきた。
これ以降は、今までの

access->open->read->fstat->mmap->mprotect->close

という(上に書いたのは大まかだが)サイクルを繰り返す。
一連のコマンドの確認ができたので、この後は新出のコマンドを調べつつ、このサイクルが終わったと考えられるところに飛ぶことにする。

気になったコマンド

munmap
このコマンドによって、これ以降のこのコマンドで指定された(マッピングされていた)領域へのアクセスは不可能になる。
arch_prctl(ARCH_SET_FS, 0x7f82a0361040) = 0
このコマンドは、アーキテクチャー固有のプロセス状態またはスレッド状態を設定する。成功しているので返り値は0。ARCH_SET_FSで、FS レジスタの 64 ビットベースを addr に設定している。
set_tid_address(0x7f82a0361310) = 175
スレッド ID へのポインタ(引数)を設定し、現在のプロセスIDを返す。
rt_sigaction
特定のシグナルを受信した際のプロセスの動作を変更するのに使用される
prlimit64
setrlimit() と getrlimit の機能を合わせて拡張したもので、任意のプロセスのリソース上限の設定と取得を行える。

終盤を丁寧に見ていく

また、ライブラリの読み込みサイクルが終わったと思われる箇所から、リファレンスを参照しながら読み解いていく。

144.ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
145.ioctl(1, TIOCGWINSZ, {ws_row=40, ws_col=83, ws_xpixel=0, ws_ypixel=0}) = 0

ioctlコマンドは、端的にはデバイスを制御するもの。
一つ目の引数でファイルディスクリプタを指定し、二つ目の引数は端末依存のリクエストコードを指定する。
144行目のリクエストコードTCGETSによって、現在のシリアルポート(ケーブル差込口)の設定を取得する。
145行目のTIOCGWINSZによって、ウインドウサイズを取得する。
三つ目の引数はコマンドを実行するための、型の決まっていない多くの引数をとる。
なお、この二つのシステムコールは成功しているために0を返す。

146.openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3

5行目でこのシステムコールについては詳しく見た。
AT_FDCWDという特別な値であるため、openシステムコールと同じようにカレントディレクトリからの相対パス名として解釈される。ここでは、カレントディレクトリを対象とする。
lsで、カレントディレクトリの中身を調べているので、大変腑に落ちる。
O_NONBLOCKで、非停止モードとなる。つまり、他のI/O操作においてもプロセスがブロックされることがない。
O_CLOEXECによって、close-on-exec フラグを有効にすることができる。
このフラグを立てておくことによって、open() を呼び出してから fcntl() を呼び出すまでのすき間の時間に、別のスレッドが子プロセスを生成してclose-on-exec フラグが設定される前のファイルディスクリプタを操作する可能性を排除できる。
O_DIRECTORYで、このファイルに対する I/O のキャッシュの効果を最小化する。
返り値は、3のfdである。

147.fstat(3, {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0

今書き込んだ3のfdの状態を読み込んで、二つ目の引数で指定したバッファに書き込む。

148.getdents(3, /* 4 entries */, 32768)     = 112
149.getdents(3, /* 0 entries */, 32768)     = 0
150.close(3)                                = 0

getdents()システムコールは、端的にはディレクトリエントリを取得するものである。
ディレクトリエントリとは、ディレクトリに含まれる各種ファイルの情報のこと。
オープン済みのfd(１つ目の引数)で参照されるディレクトリからlinux_dirent 構造体をいくつか読み出し、dirp(２つ目の引数)が指しているバッファに格納する。count(３つ目の引数)はそのバッファのサイズを示す。
ここでは、4つのディレクトリエントリを読み込んで112Byteをバッファに書き込んだことがわかる。
返り値0はディレクトリの終わりを表すので、ディレクトリの最後まで読み込んだのだと考えられる。

ちなみに、

$ ls -a
.  ..  ls.txt  strace.txt

となっており、4つのディレクトリエントリとはこれらのことである。(変更したらもちろんトレース結果も連動した)

151.fstat(1, {st_mode=S_IFCHR|0660, st_rdev=makedev(4, 1), ...}) = 0
152.ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0

151行目について、引数１つ目のfdが1というのはOSが用意した標準出力用のものであるから、標準出力用fdの状態を取得して、二つ目の引数で指定したバッファに書き込んでいる。
152行目について、リクエストコードTCGETSによって、現在のシリアルポート(ケーブル差込口)の設定を取得している。

write(1, "ls.txt\tstrace.txt\n", 18)    = 18

1のfdに(標準出力)、二つ目の引数の内容を書き込む。
また、これは18Byteであるとわかる。

153.close(1)                                = 0
154.close(2)                                = 0
155.exit_group(0)                           = ?
156.+++ exited with 0 +++

標準出力(fd=1)、標準エラー出力(fd=2)をcloseして、終了する。

全体の流れ

大雑把にまとめると、必要なライブラリの読み込みが行われ、コマンドの実行に必要な情報を収集して、それを出力している。

初めてトレースを体験することで、コンピュータがfdを駆使して情報の読み書きを行っていることを初めて知ることができた。

lsの結果をgrepする

パイプラインを用いて、ls|grep Desktopの結果をトレースしようとしたが、grep.txtにはlsコマンドのトレースのみが出力されていた。

$  strace -o grep.txt ls|grep Desktop

grepコマンドの動きが見たいと思い、トレースをしてみたところ、普段はgrepコマンドを上のようなパイプライン処理で用いていたので、使い方をまちがえてしまった。

$ strace -o grep.txt grep a

というコマンドを打ってしまった。どのデータから"a"を探すのか、というツッコミが入りそうだが、確かに一番下の行が以下のようになって、読み込みができなくて止まっていた。(貼った結果は下から二行分)

lseek(0, 0, SEEK_CUR)                   = -1 ESPIPE (Illegal seek)
read(0,

正しく実行する。
以下は、grepコマンドがls.txtの中から"ls"という文字列を抽出する様子をトレースし、その経過(システムコール)をls.txtという外部ファイルに出力するコマンドとその実行結果。
ややこしいのだが、ls.txtは、lsコマンドをトレースした結果を出力した先のファイルである。

$ strace -o grep.txt grep ls ls.txt
execve("/bin/ls", ["ls"], 0x7fffc231ae10 /* 16 vars */) = 0
write(1, " ls.txt\n", 8)                = 8

トレース結果を出力したgrep.txtを関連ライブラリを読み込んだあとの128行目から見ていく。
openatで、ls.txtのファイルを開き、その情報を3のfdに書き込んでいる。
そのあと、fstatでfdが3のファイルの状態を取得したあと、readシステムコールで、そのfdをバッファに読み込む。

128.openat(AT_FDCWD, "ls.txt", O_RDONLY|O_NOCTTY) = 3
129.fstat(3, {st_mode=S_IFREG|0777, st_size=12524, ...}) = 0
130.read(3, "execve(\"/bin/ls\", [\"ls\"], 0x7fffc231ae10 /* 16 vars */) = 0\n.........

このあとは、fstatでfd=1(標準出力)の情報を取得し、ioctlで出力を行う準備としてデバイスの制御をして、133-134行目でgrepした行を出力している。

131.fstat(1, {st_mode=S_IFCHR|0660, st_rdev=makedev(4, 1), ...}) = 0
132.ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
133.write(1, "execve(\"/bin/ls\", [\"ls\"], 0x7fffc231ae10 /* 16 vars */) = 0\n", 60) = 60
134.write(1, "write(1, \" ls.txt\\n\", 8)                = 8\n", 44) = 44

ちょっと遊んでみる

straceコマンド

lsコマンドはあまりに単純で、遊び心が出てきた。

strace strace strace

右結合というのだろうか、右二つをstraceコマンドの引数とみてくれる。
最終的には、一番右のstraceコマンドの引数がないので、+++ exited with 1 +++となって異常終了してしまう。
その直前のシステムコールは以下のようなものなので、普通に実行するときに引数が足りませんと怒られるのと同じことが起きていることが分かる。

write(2, "strace: must have PROG [ARGS] or"..., 40strace: must have PROG [ARGS] or -p PID
) = 40
write(2, "Try 'strace -h' for more informa"..., 38Try 'strace -h' for more information.
) = 38

ちなみに、strace straceでは、トレース対象のコマンド(右側のstrace)に引数がなくて無効なコマンドとして扱われるため、(左側のstraceの)実行ができなかった。

cdコマンドの謎

cdコマンドはなぜかトレースできなかった。

~$ strace cd
strace: Can't stat 'cd': No such file or directory
~$ strace cd ..
strace: Can't stat 'cd': No such file or directory

なぜかコマンドとして認識されていない(?)

参考

http://blog.livedoor.jp/sonots/archives/18193659.html
Linux Programmers Manual
Linuxシステムコール公式ドキュメント

Linuxコマンドをstrace