はじめに

curl は Web サーバや REST API の動作確認でよく利用されているコマンドです
curl が実際にどんな処理を行っているのか、strace コマンドを使用してシステムコールレベルで観察してみたいと思います
説明に間違いがありましたらごめんなさい

調査環境

Web サーバ 1 台とクライアントマシン 1 台を LAN ケーブルで直結し、OS は Linux をインストール、Web サーバは nginx を使用します
各マシンの IP アドレスは以下の通りです

マシン	IP アドレス
Web サーバ（DNS サーバと兼用）	192.168.10.1/24
クライアント	192.168.10.2/24

curl のオプション

実行する curl コマンドは以下の通りです

# curl -s -o /dev/null 192.168.10.1

このコマンドを実行すると Web サーバ (192.168.10.1) に HTTP でアクセスします
-s オプションで調査に不要な出力を抑制し、-o /dev/null でダウンロードしたファイルが標準出力に表示されないようにしています
オプションの説明

オプション	説明
-s	コマンドの出力の抑制
-o /dev/null	ダウンロードしたファイルを標準出力に表示しない

なお、今回は使用しませんが、HTTP/HTTPS レベルの動きは curl --trace-ascii - <URL> で追跡することも可能です

strace コマンド

システムコールの追跡は strace コマンドを使用します
strace コマンドの主なオプションは以下の通りです

オプション	説明
-f	子プロセスも一緒にトレースする (follow forks)
-e trace=network	ネットワーク関連のシステムコールのみをトレースする
-e write=all	ファイルディスクリプタに書き込んだデータを全て出力する
-e read=all	ファイルディスクリプタから読み込んだデータを全て出力する
-tt	タイムスタンプ付きで出力する
-T	システムコールの実行にかかった時間を出力する

トレース開始

では実際に strace コマンドを使用して curl コマンドの挙動をトレースしてみます

ネットワーク関連のシステムコールをトレースする

まずは基本形です
実行するコマンドはこちらです

# strace -e trace=network curl -s -o /dev/null 192.168.10.1

コマンドラインオプションの意味

strace コマンドに -e trace=network オプションを付けて実行するとネットワーク関連のシステムコールのみをトレースすることが出来ます
プロセスの起動・停止に関するものやライブラリのロードなど、ネットワークに直接関係ないシステムコールは省略されます
こうすることで strace の出力が膨大になって解析不能になってしまうことを防ぎます
最後にトレース対象の curl コマンドを引き数つきで指定しています

実行結果

実行結果は以下の通りです

# strace -e trace=network curl -s -o /dev/null 192.168.10.1
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(49753), sin_addr=inet_addr("192.168.10.2")}, [16]) = 0
sendto(3, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 76, MSG_NOSIGNAL, NULL, 0) = 76
recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 16384, 0, NULL, NULL) = 237
recvfrom(3, "<!DOCTYPE html>\n<html>\n<head>\n<t"..., 612, 0, NULL, NULL) = 612
+++ exited with 0 +++

strace コマンドの出力の見方

strace コマンドの出力は時系列順になっています
一つのシステムコールに対して一行の情報が出力されます
各行は、一番左がシステムコール名、カッコの中が引き数、= の右の値が返り値です
この例では、socket システムコールでソケットを作成し、connect システムコールでリモートに接続し、sendto システムコールで HTTP リクエストを送信し、recvfrom システムコールでデータを受信していることが分かります

システムコールごとの詳しい解説

先ほどの出力を 1 ステップずつ解説します

socket

socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3

まず socket システムコールでソケットを作成します
socket システムコールの返り値 "3" は作成されたソケットのファイルディスクリプタ番号です
以降のシステムコールでは引き数に 3 を渡して、このソケットを参照しています

setsockopt (SO_KEEPALIVE)

setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0

setsockopt システムコールでソケットのオプションを設定します
ここでは KEEPALIVE オプションを有効化しています
ソケットのオプションの説明は socket(7) に記載されています

setsockopt (TCP_KEEPIDLE)

setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0

setsockopt システムコールを使用して TCP の KEEPIDLE を 60 秒に設定しています
ソケットが Idle 状態になっている時間が KEEPIDLE よりも長くなると keepalive の確認パケットが送信されます
TCP のオプションは tcp(7) に記載されています

setsockopt (TCP_KEEPINTVL)

setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0

setsockopt システムコールを使用して TCP の KEEPINTVL を 60 秒に設定しています
KEEPINTVL は keepalive の確認パケットを送信する間隔です

connect

connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, 16) = -1 EINPROGRESS (Operation now in progress)

connect システムコールで HTTP サーバに接続します
ここでは IPv4(= AF_INET) で、ポート 80 番、192.168.10.1 のアドレスに接続しています
ソケットがノンブロッキングなので返り値として EINPROGRESS （処理進行中）が返ってきています
curl は connect システムコールの処理の完了を poll システムコールで待機しますが、ここでは poll システムコールのトレースを省略しているため出力されません
poll システムコールも含めたトレース方法は後述します

getsockopt

getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0

続いて getsockopt システムコールで SO_ERROR を確認し、connect システムコールが成功したかを判別しています（成功した場合は 0 が返ります）
ここでは 0 が返ってきているので成功していることが分かります

getpeername

getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0

getpeername システムコールでリモートの IP アドレスとポート番号を確認しています

getsockname

getsockname(3, {sa_family=AF_INET, sin_port=htons(49753), sin_addr=inet_addr("192.168.10.2")}, [16]) = 0

getsockname システムコールでローカルの IP アドレスとポート番号を確認しています

sendto

sendto(3, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 76, MSG_NOSIGNAL, NULL, 0) = 76

sendto システムコールで HTTP サーバに対してリクエストを送信しています
HTTP リクエストの中身は sendto の第 2 引き数にある "GET / HTTP/1.1..." です
HTTP リクエスト全文を表示する方法は後述します

recvfrom

recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 16384, 0, NULL, NULL) = 237

recvfrom システムコールで HTTP のレスポンスを受け取っています
HTTP レスポンスは recvfrom の第 2 引き数にある "HTTP/1.1 200 OK..." です
HTTP レスポンスの全文を表示する方法は後述します

recvfrom

recvfrom(3, "<!DOCTYPE html>\n<html>\n<head>\n<t"..., 612, 0, NULL, NULL) = 612

再度 recvfrom システムコールを使用して HTML データを受信しています

終了ステータス

+++ exited with 0 +++

返り値 0 で curl コマンドの実行が完了しています

poll システムコールも合わせてトレースする

trace オプションに poll の指定を追加することで poll システムコールも追跡することができます

# strace -e trace=network,poll curl -s -o /dev/null 192.168.10.1
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout)
poll([{fd=3, events=POLLOUT}], 1, 1)    = 1 ([{fd=3, revents=POLLOUT}])
poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 0) = 1 ([{fd=3, revents=POLLOUT|POLLWRNORM}])
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(49777), sin_addr=inet_addr("192.168.10.2")}, [16]) = 0
sendto(3, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 76, MSG_NOSIGNAL, NULL, 0) = 76
poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
poll([{fd=3, events=POLLIN}], 1, 1000)  = 1 ([{fd=3, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=3, revents=POLLIN|POLLRDNORM}])
recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 16384, 0, NULL, NULL) = 849
+++ exited with 0 +++

connect システムコールと sendto システムコールの後で poll システムコールを使ってソケットを待機している事が分かります

システムコールの実行タイミングをトレースする

-tt オプションを使用するとシステムコールが実行された瞬間のタイムスタンプ付きで出力されます
connect が発行されたタイミングを記録しておき Web サーバ側のログとつき合わせるといったような調査を行うことができるようになります

# strace -tt -e trace=network curl -s -o /dev/null 192.168.10.1
16:23:56.588983 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
16:23:56.589076 setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
16:23:56.589201 setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
16:23:56.589264 setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
16:23:56.589326 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
16:23:56.590095 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
16:23:56.590306 getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0
16:23:56.590464 getsockname(3, {sa_family=AF_INET, sin_port=htons(49770), sin_addr=inet_addr("192.168.10.2")}, [16]) = 0
16:23:56.590610 sendto(3, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 76, MSG_NOSIGNAL, NULL, 0) = 76
16:23:56.590995 recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 16384, 0, NULL, NULL) = 849
16:23:56.591931 +++ exited with 0 +++

タイムスタンプは各行の一番左に出力され、出力形式は HH:MM:SS.MicroSec です

DNS を引く場合

curl は DNS 問い合わせをする際に子プロセスを生成し、子プロセス側で DNS サーバに接続します
生成された子プロセスも含んだトレースを行うオプションは -f です

# strace -f -e trace=network curl -s -o /dev/null host1.example.com
socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 3
Process 27983 attached
[pid 27983] socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
[pid 27983] connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
[pid 27983] socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
[pid 27983] connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
[pid 27983] socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3
[pid 27983] connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.10.1")}, 16) = 0
[pid 27983] sendmmsg(3, {{{msg_name(0)=NULL, msg_iov(1)=[{"\356-\1\0\0\1\0\0\0\0\0\0\5host1\7example\3com\0\0"..., 35}], msg_controllen=0, msg_flags=0}, 35}, {{msg_name(0)=NULL, msg_iov(1)=[{"\241\27\1\0\0\1\0\0\0\0\0\0\5host1\7example\3com\0\0"..., 35}], msg_controllen=0, msg_flags=0}, 35}}, 2, MSG_NOSIGNAL) = 2
[pid 27983] recvfrom(3, "\356-\205\200\0\1\0\2\0\1\0\0\5host1\7example\3com\0\0"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.10.1")}, [16]) = 83
[pid 27983] recvfrom(3, "\241\27\205\200\0\1\0\1\0\1\0\0\5host1\7example\3com\0\0"..., 1965, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.10.1")}, [16]) = 112
[pid 27983] +++ exited with 0 +++
socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(49754), sin_addr=inet_addr("192.168.10.2")}, [16]) = 0
sendto(3, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 81, MSG_NOSIGNAL, NULL, 0) = 81
recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 16384, 0, NULL, NULL) = 237
recvfrom(3, "<!DOCTYPE html>\n<html>\n<head>\n<t"..., 612, 0, NULL, NULL) = 612
+++ exited with 0 +++

[pid 27983] で始まる行が子プロセスの処理をトレースしている部分です
子プロセスで実行されている部分だけ抜き出すとこんな感じになります

Process 27983 attached
[pid 27983] socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
[pid 27983] connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
[pid 27983] socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
[pid 27983] connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
[pid 27983] socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3
[pid 27983] connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.10.1")}, 16) = 0
[pid 27983] sendmmsg(3, {{{msg_name(0)=NULL, msg_iov(1)=[{"\356-\1\0\0\1\0\0\0\0\0\0\5host1\7example\3com\0\0"..., 35}], msg_controllen=0, msg_flags=0}, 35}, {{msg_name(0)=NULL, msg_iov(1)=[{"\241\27\1\0\0\1\0\0\0\0\0\0\5host1\7example\3com\0\0"..., 35}], msg_controllen=0, msg_flags=0}, 35}}, 2, MSG_NOSIGNAL) = 2
[pid 27983] recvfrom(3, "\356-\205\200\0\1\0\2\0\1\0\0\5host1\7example\3com\0\0"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.10.1")}, [16]) = 83
[pid 27983] recvfrom(3, "\241\27\205\200\0\1\0\1\0\1\0\0\5host1\7example\3com\0\0"..., 1965, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.10.1")}, [16]) = 112
[pid 27983] +++ exited with 0 +++

まず nscd に二度接続 (socket, connect) を試み、情報がキャッシュされていないかを確認し、その後 DNS サーバ (192.168.10.1) に接続 (socket, connect) して、sendmmsg で host1.example.com のアドレスを問い合わせ、recvfrom で DNS の応答を受信していることが分かります

送信リクエストのダンプ

strace コマンドに -e write=all オプションを付けて実行すると、ファイルディスクリプタ（ソケット）に対して書き込んだ全データを表示することができます
これを利用して HTTP リクエストの内容を確認することができます

# strace -e trace=network -e write=all curl -s -o /dev/null 192.168.10.1
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(49771), sin_addr=inet_addr("192.168.10.2")}, [16]) = 0
sendto(3, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 76, MSG_NOSIGNAL, NULL, 0) = 76
 | 00000  47 45 54 20 2f 20 48 54  54 50 2f 31 2e 31 0d 0a  GET / HTTP/1.1.. |
 | 00010  55 73 65 72 2d 41 67 65  6e 74 3a 20 63 75 72 6c  User-Agent: curl |
 | 00020  2f 37 2e 32 39 2e 30 0d  0a 48 6f 73 74 3a 20 31  /7.29.0..Host: 1 |
 | 00030  39 32 2e 31 36 38 2e 31  30 2e 31 0d 0a 41 63 63  92.168.10.1..Acc |
 | 00040  65 70 74 3a 20 2a 2f 2a  0d 0a 0d 0a              ept: */*....     |
recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 16384, 0, NULL, NULL) = 849
+++ exited with 0 +++

sendto システムコールの下にソケットに書き込まれたデータが全て出力されています
出力は左からオフセットアドレス、データの 16 進ダンプ、ASCII ダンプです
この出力結果から分かる HTTP リクエストは以下の通りです

GET / HTTP/1.1
User-Agent: curl/7.29.0
Host: 192.168.10.1
Accepted: */*

HTTP 1.1 の GET を発行していることが分かります
HTTP 1.1 唯一の必須ヘッダである Host ヘッダの値は 192.168.10.1 に設定されています
User-Agent は curl/7.29.0 になっています
User-Agent は -A オプションで変更可能です (ex. curl -A "Mozilla")
HTTP リクエスト、HTTP レスポンスのデータは curl --trace-ascii - <URL> コマンドでも確認できます

受信データのダンプ

strace コマンドに -e read=all オプションを付けて実行すると、ファイルディスクリプタ（ソケット）から読み込んだデータを表示することができます
これを利用して HTTP レスポンスの内容を確認することができます

# strace -e trace=network -e read=all curl -s -o /dev/null 192.168.10.1
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(49772), sin_addr=inet_addr("192.168.10.2")}, [16]) = 0
sendto(3, "GET / HTTP/1.1\r\nUser-Agent: curl"..., 76, MSG_NOSIGNAL, NULL, 0) = 76
recvfrom(3, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 16384, 0, NULL, NULL) = 237
 | 00000  48 54 54 50 2f 31 2e 31  20 32 30 30 20 4f 4b 0d  HTTP/1.1 200 OK. |
 | 00010  0a 53 65 72 76 65 72 3a  20 6e 67 69 6e 78 2f 31  .Server: nginx/1 |
 | 00020  2e 38 2e 31 0d 0a 44 61  74 65 3a 20 54 68 75 2c  .8.1..Date: Thu, |
 | 00030  20 30 37 20 41 70 72 20  32 30 31 36 20 30 37 3a   07 Apr 2016 07: |
 | 00040  32 39 3a 34 32 20 47 4d  54 0d 0a 43 6f 6e 74 65  29:42 GMT..Conte |
 | 00050  6e 74 2d 54 79 70 65 3a  20 74 65 78 74 2f 68 74  nt-Type: text/ht |
 | 00060  6d 6c 0d 0a 43 6f 6e 74  65 6e 74 2d 4c 65 6e 67  ml..Content-Leng |
... 以下略

recvfrom システムコールの情報に続いて、recvfrom で読み込まれたデータが表示されています
出力形式は -e write=all の時と同じです
受信したデータは以下の通りです

HTTP/1.1 200 OK
Server: nginx/1.8.1
Date: Thu,07 Apr 2016 07:29:42 GMT
Content-Type: text/html
Content-Leng
... 以下略

HTTP ステータスコードは 200 で正常にアクセス出来ていることが分かります
それに続くヘッダの情報も HTTP 通信の解析に役に立ちます

まとめ

以上、strace を使用して curl の挙動を確認してみました
curl が何をやっているか、同等の処理を自分で実装するとしたらどんなプログラムを書けば良いか、何となく見えてくると思います

おしまい