システムコールトレーシング: 吸い込まれる標準入力を観察する
Linuxその2 Advent Calendar 2020 18 日目の記事です。
「スクリプト書いてたんですが、なぜか途中で止まるんです」と言われた。
確かに yarn gen で止まっている。 yarn start も date も実行されていない。終了コードは 0 で、正常だ。
「ファイルとして実行してみて」と伝えた。
最後まで実行された。
雰囲気で「たぶん 標準入力が吸い込まれている」と雑返答をしてしまったが、ここでその正体を明らかにしておきたい。
1. strace でシステムコールを記録する
ソースコードを読むより strace コマンドで挙動を追うのが好きなので、 bash に strace をアタッチしてシステムコールを記録させる。
$ strace -p 10088 -f 2>&1 | tee strace.bash.log strace: Process 10088 attached pselect6(1, [0], NULL, NULL, NULL, {[], 8} ## この状態で、アタッチ中の bash に対して「途中で止まる」スクリプトを入力する ## ``` ## bash <<EOF ## date ## yarn gen ## yarn start ## date ## EOF ## ``` (大量のトレース結果) ## Ctrl+C でデタッチする ^Cstrace: Process 10088 detached <detached ...> $ wc -l strace.bash.log 33677 strace.bash.log
2. システムコールから挙動を観察する
2-1. ヒアドキュメントの書き出し
clone システムコールで子プロセスが作成し、その子プロセスでヒアドキュメントを書き出している。
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLDstrace: Process 11360 attached
, child_tidptr=0x7f6ed3e90a10) = 11360
[pid 11360] openat(AT_FDCWD, "/tmp/sh-thd.7rsuca", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
[pid 11360] fchmod(3, 0600) = 0
[pid 11360] fcntl(3, F_SETFD, FD_CLOEXEC) = 0
[pid 11360] dup(3) = 4
[pid 11360] fcntl(4, F_GETFL) = 0x8002 (flags O_RDWR|O_LARGEFILE)
[pid 11360] fstat(4, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
[pid 11360] write(4, "date\nyarn gen\nyarn start\ndate\n", 30) = 30
[pid 11360] close(4) = 0
2-2. 標準入力をヒアドキュメントに差し替え
書き出したヒアドキュメントは、読み取り専用で開き直してファイルディスクリプタ 0 (stdin) に複製する。すなわち子プロセスの 標準入力をヒアドキュメントに差し替えている 。
[pid 11360] openat(AT_FDCWD, "/tmp/sh-thd.7rsuca", O_RDONLY) = 4
[pid 11360] close(3) = 0
[pid 11360] unlink("/tmp/sh-thd.7rsuca") = 0
[pid 11360] fchmod(4, 0400) = 0
[pid 11360] dup2(4, 0) = 0
[pid 11360] close(4) = 0
2-3. bash を実行
execve で、この子プロセスが bash に置き換わる。
[pid 11360] execve("/usr/bin/bash", ["bash"], 0x5642bbf4ca80 /* 25 vars */) = 0
2-4. 標準入力を読み込み
標準入力 (実体はファイルである) の先頭にシークして一気に読み込む。
fstat でサイズを調べて、 read でそのサイズ分を一気に読んでいるようだ。
[pid 11360] fcntl(0, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE)
[pid 11360] fstat(0, {st_mode=S_IFREG|0400, st_size=30, ...}) = 0
[pid 11360] lseek(0, 0, SEEK_CUR) = 0
[pid 11360] read(0, "date\nyarn gen\nyarn start\ndate\n", 30) = 30
2-5. date コマンドを探す
最初は date コマンドであることが分かったので、 PATH を順番に探しているようだ。
[pid 11360] stat("/home/linuxbrew/.linuxbrew/bin/date", 0x7fffccf3db80) = -1 ENOENT (No such file or directory)
[pid 11360] stat("/usr/local/sbin/date", 0x7fffccf3db80) = -1 ENOENT (No such file or directory)
[pid 11360] stat("/usr/local/bin/date", 0x7fffccf3db80) = -1 ENOENT (No such file or directory)
[pid 11360] stat("/usr/sbin/date", 0x7fffccf3db80) = -1 ENOENT (No such file or directory)
[pid 11360] stat("/usr/bin/date", {st_mode=S_IFREG|0755, st_size=108920, ...}) = 0
2-6. 標準入力をシークしなおし、 date を実行する
ここがポイントである。 読みすぎた標準入力のシーク位置を巻き戻している。 次の read でちょうど yarn gen 以降が読み込める位置だ。
clone でまた子プロセスを生成し、 bash は子プロセス終了を待つ。子プロセスは execve によって date に置換され実行されているが、詳細は省く。
[pid 11360] lseek(0, -25, SEEK_CUR) = 5
[pid 11360] clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLDstrace: Process 11361 attached
, child_tidptr=0x7f685563ca10) = 11361
[pid 11360] wait4(-1, <unfinished ...>
[pid 11361] execve("/usr/bin/date", ["date"], 0x55df84d668b0 /* 25 vars */) = 0
(略)
[pid 11361] exit_group(0) = ?
[pid 11361] +++ exited with 0 +++
[pid 11360] <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 11361
2-7. 標準入力を再度読み込み
bash に戻ってきて、標準入力をまた読み込む。今度は yarn gen 以降を読み取る。
[pid 11360] read(0, "yarn gen\nyarn start\ndate\n", 30) = 25
2-8. yarn を探し、標準入力をシークし、実行し、そして…？
yarn コマンドが実行されるまでは date コマンドと同じ、コマンド検索 & シーク & 実行である。
シーク位置は、次に yarn start 以降が読み込まれる箇所だ。
[pid 11360] stat("/home/linuxbrew/.linuxbrew/bin/yarn", 0x7fffccf3db80) = -1 ENOENT (No such file or directory)
[pid 11360] stat("/home/typewriter/.nodenv/shims/yarn", {st_mode=S_IFREG|0755, st_size=405, ...}) = 0
[pid 11360] lseek(0, -16, SEEK_CUR) = 14
[pid 11360] clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLDstrace: Process 11362 attached
<unfinished ...>
[pid 11360] wait4(-1, <unfinished ...>
[pid 11362] execve("/home/typewriter/.nodenv/shims/yarn", ["yarn", "gen"], 0x55df84d66f70 /* 25 vars */) = 0
しかし、問題はこの先である。子プロセスを何度か作成し、 run-p コマンド（に置換されたプロセス）の子プロセス (pid: 11409) に辿り着く。 yarn start\ndate\n を読み込んでしまっている。
[pid 11362] clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLDstrace: Process 11400 attached
<unfinished ...>
[pid 11400] clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLDstrace: Process 11401 attached
<unfinished ...>
[pid 11401] execve("/home/typewriter/.nodenv/versions/12.18.3/bin/run-p", ["run-p", "-s", "--print-label", "gen:*"], 0x55dcfacf6f68 /* 58 vars */ <unfinished ...>
[pid 11401] clone(child_stack=0x7f6061052f70, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTIDstrace: Process 11409 attached
<unfinished ...>
[pid 11409] read(0, <unfinished ...>
(略)
[pid 11409] <... read resumed>"yarn start\ndate\n", 65536) = 16
2-9. 標準入力は空っぽ。完
yarn gen が終わり、次に標準入力を読むと、空になってしまっている。 yarn start と date が実行されないまま bash が終了する。
[pid 11362] +++ exited with 0 +++
[pid 11360] <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 11362
[pid 11360] read(0, "", 30) = 0
[pid 11360] exit_group(0) = ?
[pid 11360] +++ exited with 0 +++
<... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WSTOPPED|WCONTINUED, NULL) = 11360
観察した挙動をまとめる
標準入力にまつわる一連の挙動を整理するとこうだ。
3. ドキュメントから挙動を解釈する
挙動は整理できたが、なぜこのような挙動をするのか、ドキュメントから解釈していく。
read, lseek によるファイルのオフセットの変更
read するとオフセットが進むが、 lseek で自由に変更できる。
seek に対応しているファイルでは、read は現在のファイルオフセットから行われ、ファイルオフセットは読み込んだバイト数分だけ進められる。
lseek() 関数は、ファイルディスクリプター (descriptor) fd に対応するオープンされたファイルのオフセットを、 whence に基づき offset 引き数の位置へ以下のように変更する (略)
標準入力を共有している挙動
標準入力、標準出力、標準エラー出力は、ファイルディスクリプタ 0, 1, 2 に割り当てられている。
プログラムの起動時には、 ストリーム stdin, stdout, stderr に結びつけられているファイルディスクリプターの番号は、 それぞれ 0, 1, 2 である。
そして、 clone システムコールのドキュメントを読むと、ファイルディスクリプタを共有または複製するとある。今回は、（ run-p を除き） CLONE_FILES フラグが設定されていないため、 複製 されている。いずれにせよ、 bash の標準入力を date や yarn が共有するのは確かなようだ。
CLONE_FILES (Linux 2.0 以降)
CLONE_FILES が設定された場合、呼び出し元のプロセスと子プロセスはファイルディスクリプターの テーブルを共有する。 (略)
CLONE_FILES が設定されていない場合、子プロセスは、 clone() が実行された時点で、呼び出し元のプロセスがオープンしている全ての ファイルディスクリプターのコピーを継承する (子プロセスの複製されたファイルディスクリプターは、 対応する呼び出し元のプロセスのファイルディスクリプターと 同じファイル記述 (open(2) 参照) を参照する)。 これ以降に、呼び出し元のプロセスと子プロセスの一方が ファイルディスクリプターの操作 (ファイルディスクリプターの オープン・クローズや、ファイルディスクリプターフラグの変更) を行っても、もう一方のプロセスには影響を与えない。
標準入力のシーク位置を共有している挙動
さきほどの clone のドキュメントには、「呼び出し元のプロセスのファイルディスクリプターと 同じファイル記述 (open(2) 参照) を参照する」とあった。「ファイル記述」とはなにか、 open システムコールのドキュメントを参照する。
ファイル記述とは、システム全体のオープン中のファイルのテーブルのエントリーである。 このオープンファイル記述は、ファイルオフセットとファイル状態フラグ (下記参照) が保持する。 ファイルディスクリプターはオープンファイルっ記述への参照である。 (※原文ママ)
「ファイルディスクリプタ」と「ファイル記述」は名前が似ているが別物のようだ。図にするとこうだろうか？
ここで重要なのは、どのプロセスも同じ「ファイル記述」を指していて、ファイルオフセットを共有しているということだ。
つまり、「たぶん 標準入力が吸い込まれている」の正体は、「bash と同じファイル記述を共有する孫プロセス run-p が標準入力を read したためにファイルオフセットが進んでしまい、 bash は標準入力から何も読み取れずに終了した」ということだった。
おまけ: ファイルとして実行した場合の挙動
ファイルとして実行した場合は、ファイルディスクリプタ 255 に割り当てて読み取っている。これにより、子プロセスが標準入力をいくら吸い取っても問題にはならない。 255 には何か意味があるようだが 、未調査のため割愛する。
[pid 12990] lseek(255, 0, SEEK_CUR) = 0 [pid 12990] read(255, "#!/bin/bash\n\ndate\nyarn gen\nyarn "..., 43) = 43
まとめ
- 標準入力をすげかえない限り、標準入力やそのオフセット（を含むファイル記述）は子プロセスと共有される。
- 子プロセスが標準入力を read してしまうと、オフセットが進んで親プロセス bash が読みたかったコマンドを通り過ぎてしまう。
