はじめに
TCPの仕様やconnect、write、read等のソケット関連のシステムコールの振る舞いを正確に理解するのはとても難しい。
正常系はそうでもないが、「どの程度パケットは再送されるのか」、「〜状態で〜のシステムコールはどのerrnoを返すのか」など異常系が難しい。また、これらの情報はWEB上だと良質な情報が比較的少ないように思う。
ここでは、挙動の説明は諦め1、挙動を確認するためのコマンドやコード群を紹介したい。
なお、普通のバックエンドエンジニアをしている人間で、ネットワークのスペシャリストではないので間違っている可能性は多分にある。ただ、ここで説明することは全て動作確認はしている。動作確認した環境はこちらにある。
コマンド
説明
ss -tanpo
tcp(t)の全状態(a)をポート番号のまま(n)プロセス情報(p)とタイマー情報付き(o)で表示する。
ssは継続的な状態確認には向いてないので以下のように結果を垂れ流しておくとよい。
while true; do date; ss -tanpo; sleep 5; done
タイマーについて
タイマーは馴染みがない人も多そうなので補足すると以下の挙動をする。
タイマーは以下の種類がある。TCP_USER_TIMEOUT等の説明は多くの人は無視してしまっていい。2
要はタイマーにいろいろな種類があり、それをssコマンドで確認することができる。ソケットの状態を確認するのにとても役に立つのでとりあえず出力しておくと原因調査等に役立つかもしれない。
- on
- クライアントによるSYNの再送。TCP_USER_TIMEOUT即時
- サーバによるSYNACKの再送。SYN-RECV状態のsocketはmini-socketと呼ばれ、アプリケーションから制御不能なため、TCP_USER_TIMEOUT設定不可能
- データパケットの再送。TCP_USER_TIMEOUT即時
- keepalive
- tcp keepalive。TCP_USER_TIMEOUTは再送時check
- タイムアウト時にRSTを飛ばす
- timewait
- FIN-WAIT-2のものがCLOSEDに自動で移行するまでのタイムアウト
- tcp_fin_timeout(デフォルト60秒)
- tcpの仕様に反している挙動。passive close側がCLOSE-WAITで残り続け、誤って新しいコネクションを続きであると思ってしまう可能性あり
- 確認する限り、ソケットを明示的にcloseしないと起動しない。shutdownではダメ。
- CLOSE-WAITのものがCLOSEDに自動で移行するタイムアウト
- いわゆる 2 * MSLで2分と言われることが多いが、linuxは固定で60秒3
- FIN-WAIT-2のものがCLOSEDに自動で移行するまでのタイムアウト
- persist
- 受信バッファが一杯のため、window probeを再送。TCP_USER_TIMEOUTは再送時check
- window probeのackがないため再送。TCP_USER_TIMEOUTは再送時check
Recv-Q/Send-Q
-
LISTEN以外について- Recv-Qは、カーネルの受信バッファに残っているデータのバイト数
- 例えば、サーバが
Readしなかったり、そもそもAcceptしなかった場合には溜まる一方になる。
- 例えば、サーバが
- Send-Qは、カーネルの送信バッファに残っているデータのバイト数
- 例えば、クライアントでWriteが成功しているものの、パケットがどこかで破棄されている場合、一向にACKを受け取らず、溜まる一方になる。
- Recv-Qは、カーネルの受信バッファに残っているデータのバイト数
-
LISTENについて- 前提知識として、SYNキュー、Acceptキューを説明する。
- SYNキューはSYNを受け取ってSYNACKを返しているがACKを受け取れていないキュー
- AcceptキューはACKを受け取っているがアプリケーションからAcceptされていないキュー
- コネクションという観点ではESTABLISHED
- Recv-Qは、Acceptキューの要素数4
- 例えば、サーバがそもそも
Acceptしなかった場合には溜まる一方になる。
- 例えば、サーバがそもそも
- Send-Qは、Acceptキューのキャパシティ
-
int listen(int sockfd, int backlog)のbacklogのこと - Kernels 4.3以降はAcceptキューとSYNキューのキャパシティは同じ
-
- 前提知識として、SYNキュー、Acceptキューを説明する。
tcpdump -i lo -n -X -s0 port 8080 or icmp
インターフェースを指定して(i)アドレスやポート番号を名前に変換せず(n)16進数とASCII両方(X)をデータを切り詰めず(s0)に、fromかtoが8080ポートもしくはicmpパケットを表示する。
注意点として、以下manの引用にあるようにローカル間の疎通を確認する場合には、-i loを明示的に指定する必要がある。
Listen on interface. If unspecified, tcpdump searches the system interface list for the lowest numbered, configured up inter-
face (excluding loopback), which may turn out to be, for example, ``eth0''.
strace -Ttt -s 1024 -e trace=network,read,write,poll,fcntl (コマンド or -p pid)
実行時刻をマイクロ秒精度で表示(tt)しシステムコールの実行時間を末尾に秒単位(T)にて、一行に表示する文字数を1024までにし(s 1024)、ネットワーク関連のシステムコール(network)と指定のシステムコール実行履歴を表示する。
場合によっては、open close等も指定したほうがいいかもしれないけど、出力が多くなり見辛くなるので状況を見つつ。また、子プロセスも表示させる場合には-fも指定。
コツとしては、最初はtrace指定でフィルターをせずに利用されているシステムコールをざっと把握すると良い。無駄な出力が多い場合は!で除外指定すると良い。以下はGolangの例。!がシェルだと特別な意味を持つのでエスケープが必要
strace -Ttt -s 1024 -f -e 'trace=!clock_gettime,futex' ./main
nc -kl -p 8080
tcpkeepaliveを有効にして(k)、ポート8080をlisten(l)する
nc api.local 8080
ポート8080に接続する
iptables -A INPUT -p tcp --dport 8080 -j DROP
入力(INPUT)のtcp通信(-p tcp)でポート8080をdestinationとする(-dport)パケットを削除する(DROP)ルールを追加(A)する。
iptables -A INPUT -p tcp --dport 8080 -j DROP --tcp-flags SYN,RST,ACK SYN,ACK
SYN,RST,ACKの中で、SYN,ACKビットが立っているパケットが対象。
SYN -> SYNACK -> ACKのフローでSYNACKだけ届かないケースなどを再現するときに使える。
iptables -nvL INPUT --line-numbers
入力(INPUT)のルールを名前解決せずに(n)詳細に(v)行番号付きで(--line-numbers)リストする(L)
iptables -D INPUT 1
入力(INPUT)の1番目の行番号のルールを削除(-D)する
例
ncコマンドの例
ncコマンドにてkオプションをつけてkeepaliveを有効にして8080ポートをLISTENし起動。
クライアントからncにて接続し、keepaliveのパケットが飛ぶこと、そのときのタイマーの様子、途中でパケットをDROPするようにしてエラーになることを確かめる。
# @server
# 動作確認しやすいようkeepaliveの設定を短めに設定する
$ sysctl -w \
> net.ipv4.tcp_keepalive_time=30 \
> net.ipv4.tcp_keepalive_probes=3 \
> net.ipv4.tcp_keepalive_intvl=5
# Send first keepalive probe after 30(default 7200) seconds of idleness.
net.ipv4.tcp_keepalive_time = 30
# Time out after 3(default 9) failed probes.
net.ipv4.tcp_keepalive_probes = 3
# Send subsequent keepalive probes after 5(default 75) seconds
net.ipv4.tcp_keepalive_intvl = 5
# 8080をListenしてサーバ起動
$ strace -Ttt -s 1024 -e trace=network,read,write,poll,fcntl,open,close nc -klp 8080
.
.
08:44:20.241577 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3 <0.000323>
08:44:20.243318 setsockopt(3, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0 <0.000398>
08:44:20.244405 setsockopt(3, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0 <0.000232>
# ncにkオプションをつけないとこの行は存在しない。keepaliveを有効にしている
08:44:20.245035 setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 <0.000156>
08:44:20.246063 bind(3, {sa_family=AF_INET, sin_port=htons(8080), sin_addr=inet_addr("0.0.0.0")}, 16) = 0 <0.000413>
# backlog=1である。ncの挙動として接続したらすぐcloseするのでbacklog=1でいいのだろう
08:44:20.246849 listen(3, 1) = 0 <0.000732>
# <5.423271>より、5.4秒ほどacceptがブロックされていることがわかる
08:44:20.249840 accept(3, {sa_family=AF_INET, sin_port=htons(38970), sin_addr=inet_addr("173.21.6.32")}, [16]) = 4 <5.423271>
08:44:25.674720 close(3) = 0 <0.000119>
08:44:25.675445 getsockname(4, {sa_family=AF_INET, sin_port=htons(8080), sin_addr=inet_addr("173.21.6.31")}, [16]) = 0 <0.000495>
# クライアントがfirstを送ってきた。改行ふくめ6byte
08:44:45.778712 read(4, "first\n", 8192) = 6 <0.000183>
# 標準出力に出力
08:44:45.779162 write(1, "first\n", 6first
) = 6 <0.000226>
second
# 標準入力からsecondを入力し、クライアントに送る
08:46:41.805522 read(0, "second\n", 8192) = 7 <0.000039>
08:46:41.805707 write(4, "second\n", 7) = 7 <0.000389>
# サーバ側で8080をdestinationとしたINPUTパケットを破棄するよう設定した結果keepaliveのパケットをリトライ後readがETIMEDOUTにてエラー
08:48:27.920128 read(4, 0x95d060, 8192) = -1 ETIMEDOUT (Connection timed out) <0.000185>
08:48:27.920564 close(4) = 0 <0.000076>
08:48:27.921257 +++ exited with 0 +++
クライアントは、
# @client
$ strace -Ttt -s 1024 -e trace=network,read,write,poll,fcntl,open,close nc -api.local 8080
.
.
08:44:25.663583 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3 <0.002015>
08:44:25.667759 setsockopt(3, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0 <0.000499>
08:44:25.668587 setsockopt(3, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0 <0.000318>
08:44:25.672203 connect(3, {sa_family=AF_INET, sin_port=htons(8080), sin_addr=inet_addr("173.21.6.31")}, 16) = 0 <0.001052>
first
# firstを送る
08:44:45.777639 read(0, "first\n", 8192) = 6 <0.000072>
08:44:45.777805 write(3, "first\n", 6) = 6 <0.000867>
# secondを受け取る
08:46:41.806626 read(3, "second\n", 8192) = 7 <0.000380>
08:46:41.807250 write(1, "second\n", 7second
) = 7 <0.000861>
# サーバからRSTパケットを受け取りECONNRESETにてreadがエラー
08:48:27.922989 read(3, 0x1fdb060, 8192) = -1 ECONNRESET (Connection reset by peer) <0.000530>
08:48:27.924516 close(3) = 0 <0.000168>
08:48:27.925284 close(3) = -1 EBADF (Bad file descriptor) <0.000414>
サーバ側にて、while true; do date; ss -tanpo; sleep 5; doneしていると、keepaliveのタイマーが30秒のカウントダウンをして、パケットを送り、そのACKをうけとり、30秒のカウントダウンを開始といったように、loopしていることが確かめられる。
net.ipv4.tcp_keepalive_time(=30)は通信がidleになってからの経過秒数である。
以下のssコマンドのログでは、08:46:46にちょうどタイマーが0になっているが、08:46:41に文字列「second\n」のパケット通信があったため、keepaliveのパケットを飛ばさずに25秒にタイマーを設定し直していることがわかる(5秒後のタイマーが20秒である)。
つまり、タイマー切れを迎えてもそのタイミングでパケットが飛ぶとは限らずにチェックする処理が起こされそこで改めて判断されるようだ。
タイマー中にパケット通信があった場合のssコマンドのログ
# @server
Sun Apr 11 08:46:41 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
ESTAB 0 0 173.21.6.31:8080 173.21.6.32:38970 users:(("nc",pid=2128,fd=4)) timer:(keepalive,4.858ms,0)
Sun Apr 11 08:46:46 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
ESTAB 0 0 173.21.6.31:8080 173.21.6.32:38970 users:(("nc",pid=2128,fd=4)) timer:(keepalive,,0)
Sun Apr 11 08:46:51 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
ESTAB 0 0 173.21.6.31:8080 173.21.6.32:38970 users:(("nc",pid=2128,fd=4)) timer:(keepalive,20sec,0)
その後、サーバにて、iptables -A INPUT -p tcp --dport 8080 -j DROPを行い、入力のtcp通信でポート8080をdestinationとするパケットを削除するルールを追加する。
timerのみ抜き出すと、以下のように5秒おきにkeepaliveのパケットを送り、3回目の再送のタイミングにて、再送せずにRSTを飛ばしていることがわかる。
timer:(keepalive,719ms,0)
# ここでkeepaliveパケットを飛ばす。ACKを受け取れば次回は30秒後であるが受け取れないため、5秒後に再送する
timer:(keepalive,917ms,1)
# 1回目の再送
timer:(keepalive,1.026ms,2)
# 2回目の再送
timer:(keepalive,1.138ms,3)
# 3回目の再送はせずにここでRSTを飛ばす
サーバ側で8080をdestinationとしたINPUTパケットを破棄するよう設定した際のサーバ側のssのログ
# @server
Sun Apr 11 08:48:11 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
ESTAB 0 0 173.21.6.31:8080 173.21.6.32:38970 users:(("nc",pid=2128,fd=4)) timer:(keepalive,719ms,0)
Sun Apr 11 08:48:16 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
ESTAB 0 0 173.21.6.31:8080 173.21.6.32:38970 users:(("nc",pid=2128,fd=4)) timer:(keepalive,917ms,1)
Sun Apr 11 08:48:21 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
ESTAB 0 0 173.21.6.31:8080 173.21.6.32:38970 users:(("nc",pid=2128,fd=4)) timer:(keepalive,1.026ms,2)
Sun Apr 11 08:48:26 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
ESTAB 0 0 173.21.6.31:8080 173.21.6.32:38970 users:(("nc",pid=2128,fd=4)) timer:(keepalive,1.138ms,3)
Sun Apr 11 08:48:31 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
Sun Apr 11 08:48:36 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
Sun Apr 11 08:48:41 Asia 2021
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.11:33101 *:*
サーバ側で8080をdestinationとしたINPUTパケットを破棄するよう設定した際のサーバ側のtcpdumpのログ
# @server
08:48:12.592519 IP 173.21.6.31.8080 > 173.21.6.32.38970: Flags [.], ack 7, win 510, options [nop,nop,TS val 2274775744 ecr 3399543988], length 0
0x0000: 4500 0034 31a5 4000 4006 a2b5 ad15 061f E..41.@.@.......
0x0010: ad15 0620 1f90 983a e352 c151 62f4 cb50 .......:.R.Qb..P
0x0020: 8010 01fe 6690 0000 0101 080a 8796 52c0 ....f.........R.
0x0030: caa0 ecb4 ....
# 173.21.6.32.38970からのACKであるが、これらのパケットは全て破棄されていることに注意
08:48:12.593014 IP 173.21.6.32.38970 > 173.21.6.31.8080: Flags [.], ack 8, win 502, options [nop,nop,TS val 3399574194 ecr 2274684855], length 0
0x0000: 4500 0034 7513 4000 4006 5f47 ad15 0620 E..4u.@.@._G....
0x0010: ad15 061f 983a 1f90 62f4 cb50 e352 c152 .....:..b..P.R.R
0x0020: 8010 01f6 6690 0000 0101 080a caa1 62b2 ....f.........b.
0x0030: 8794 efb7 ....
08:48:17.710953 IP 173.21.6.31.8080 > 173.21.6.32.38970: Flags [.], ack 7, win 510, options [nop,nop,TS val 2274780863 ecr 3399543988], length 0
0x0000: 4500 0034 31a6 4000 4006 a2b4 ad15 061f E..41.@.@.......
0x0010: ad15 0620 1f90 983a e352 c151 62f4 cb50 .......:.R.Qb..P
0x0020: 8010 01fe 6690 0000 0101 080a 8796 66bf ....f.........f.
0x0030: caa0 ecb4 ....
08:48:17.711329 IP 173.21.6.32.38970 > 173.21.6.31.8080: Flags [.], ack 8, win 502, options [nop,nop,TS val 3399579312 ecr 2274684855], length 0
0x0000: 4500 0034 7514 4000 4006 5f46 ad15 0620 E..4u.@.@._F....
0x0010: ad15 061f 983a 1f90 62f4 cb50 e352 c152 .....:..b..P.R.R
0x0020: 8010 01f6 6690 0000 0101 080a caa1 76b0 ....f.........v.
0x0030: 8794 efb7 ....
08:48:22.798162 IP 173.21.6.31.8080 > 173.21.6.32.38970: Flags [.], ack 7, win 510, options [nop,nop,TS val 2274785984 ecr 3399543988], length 0
0x0000: 4500 0034 31a7 4000 4006 a2b3 ad15 061f E..41.@.@.......
0x0010: ad15 0620 1f90 983a e352 c151 62f4 cb50 .......:.R.Qb..P
0x0020: 8010 01fe 6690 0000 0101 080a 8796 7ac0 ....f.........z.
0x0030: caa0 ecb4 ....
08:48:22.798439 IP 173.21.6.32.38970 > 173.21.6.31.8080: Flags [.], ack 8, win 502, options [nop,nop,TS val 3399584433 ecr 2274684855], length 0
0x0000: 4500 0034 7515 4000 4006 5f45 ad15 0620 E..4u.@.@._E....
0x0010: ad15 061f 983a 1f90 62f4 cb50 e352 c152 .....:..b..P.R.R
0x0020: 8010 01f6 6690 0000 0101 080a caa1 8ab1 ....f...........
0x0030: 8794 efb7 ....
# RSTをとばす
08:48:27.919860 IP 173.21.6.31.8080 > 173.21.6.32.38970: Flags [R.], seq 8, ack 7, win 510, options [nop,nop,TS val 2274791106 ecr 3399543988], length 0
0x0000: 4500 0034 31a8 4000 4006 a2b2 ad15 061f E..41.@.@.......
0x0010: ad15 0620 1f90 983a e352 c152 62f4 cb50 .......:.R.Rb..P
0x0020: 8014 01fe 6690 0000 0101 080a 8796 8ec2 ....f...........
0x0030: caa0 ecb4
straceの出力にもどると、サーバ側でtcpkeepalive判定にてNGとなった瞬間にreadが[ETIMEDOUT](Connection timed out)で返ることがわかる。
クライアント側ではreadにて[ECONNRESET]Connection reset by peerが返る。
もろもろの検証がおわったら忘れずに、iptableやsysctl -wによる設定を戻しておく。
curlの例
こちらはちょくちょく運用で経験することが多いと思う。
まずは、疎通できるサーバのLISTENしていないポートにcurlする。
$ strace -Ttt -s 1024 -e trace=network,poll,fcntl curl http://api.local:8080/
13:41:23.013773 fcntl(3, F_GETFD) = 0 <0.000842>
13:41:23.015408 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000656>
13:41:23.027156 socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 4 <0.000779>
13:41:23.036537 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 4 <0.000815>
# keepaliveは指定しているよう。また、TCP_KEEPIDLE/TCP_KEEPINTVLを明示的に指定している
13:41:23.038286 setsockopt(4, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 <0.000895>
13:41:23.040174 setsockopt(4, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0 <0.000965>
13:41:23.042129 setsockopt(4, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0 <0.000906>
13:41:23.043894 fcntl(4, F_GETFL) = 0x2 (flags O_RDWR) <0.000570>
# O_NONBLOCKにしている
13:41:23.045246 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000690>
# EINPROGRESSをうけとる
13:41:23.047249 connect(4, {sa_family=AF_INET, sin_port=htons(8080), sin_addr=inet_addr("173.21.6.31")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.005448>
# pollで確認
13:41:23.053289 poll([{fd=4, events=POLLOUT|POLLWRNORM}], 1, 0) = 1 ([{fd=4, revents=POLLOUT|POLLWRNORM|POLLERR|POLLHUP}]) <0.000030>
# getsockoptで確認すると、ECONNREFUSED
13:41:23.053544 getsockopt(4, SOL_SOCKET, SO_ERROR, [111], [4]) = 0 <0.000027>
curl: (7) Failed to connect to api.local port 8080: Connection refused
13:41:23.060121 +++ exited with 7 +++
即座に[ECONNREFUSED](Connection refused)にてエラーになる。
また、tcpdumpのログは以下の二つだけで、サーバが即座にSYNに対してRSTを送っていることがわかる。RSTのソースポートがちゃんと8080になっているのが興味深い。8080をLISTENしているプロセスはないので、OSが返していると思われる。
13:41:23.048033 IP 173.21.6.32.50528 > 173.21.6.31.8080: Flags [S], seq 2371493152, win 64240, options [mss 1460,sackOK,TS val 3405136391 ecr 0,nop,wscale 7], length 0
0x0000: 4500 003c eb10 4000 4006 e941 ad15 0620 E..<..@.@..A....
0x0010: ad15 061f c560 1f90 8d5a 1d20 0000 0000 .....`...Z......
0x0020: a002 faf0 6698 0000 0204 05b4 0402 080a ....f...........
0x0030: caf6 4207 0000 0000 0103 0307 ..B.........
13:41:23.048103 IP 173.21.6.31.8080 > 173.21.6.32.50528: Flags [R.], seq 0, ack 2371493153, win 0, length 0
0x0000: 4500 0028 0000 4000 4006 d466 ad15 061f E..(..@.@..f....
0x0010: ad15 0620 1f90 c560 0000 0000 8d5a 1d21 .......`.....Z.!
0x0020: 5014 0000 b9fa 0000 P.......
ここで、クライアントにて、iptables -A INPUT -p tcp --sport 8080 -j DROPをしてサーバからのRSTが届かないようにしてみる。
$ strace -Ttt -s 1024 -e trace=network,poll,fcntl curl http://api.local:8080/
13:51:20.235895 fcntl(3, F_GETFD) = 0 <0.000824>
13:51:20.237372 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000634>
13:51:20.249234 socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 4 <0.000709>
13:51:20.258181 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 4 <0.000746>
13:51:20.259785 setsockopt(4, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 <0.000519>
13:51:20.260970 setsockopt(4, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0 <0.000583>
13:51:20.262327 setsockopt(4, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0 <0.000776>
13:51:20.263899 fcntl(4, F_GETFL) = 0x2 (flags O_RDWR) <0.000719>
13:51:20.265465 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000808>
13:51:20.267679 connect(4, {sa_family=AF_INET, sin_port=htons(8080), sin_addr=inet_addr("173.21.6.31")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.001022>
13:51:20.279520 poll([{fd=4, events=POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout) <0.000863>
13:51:20.283526 poll([{fd=4, events=POLLOUT}], 1, 175) = 0 (Timeout) <0.177976>
13:51:20.463320 poll([{fd=4, events=POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout) <0.000037>
13:51:20.463600 poll([{fd=4, events=POLLOUT}], 1, 1000) = 0 (Timeout) <1.006143>
13:51:21.470361 poll([{fd=4, events=POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout) <0.000034>
.
.
13:51:51.600727 poll([{fd=4, events=POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout) <0.000029>
# timeoutは1秒。ここで初めて1が返る。POLLOUT|POLLERR|POLLHUPにbitが立っている。
13:51:51.601170 poll([{fd=4, events=POLLOUT}], 1, 1000) = 1 ([{fd=4, revents=POLLOUT|POLLERR|POLLHUP}]) <0.654999>
# 引数を変えて改めてpoll
13:51:52.256600 poll([{fd=4, events=POLLOUT|POLLWRNORM}], 1, 0) = 1 ([{fd=4, revents=POLLOUT|POLLWRNORM|POLLERR|POLLHUP}]) <0.000038>
# getsockoptにて[ETIMEDOUT](Connection timed out)
13:51:52.257313 getsockopt(4, SOL_SOCKET, SO_ERROR, [110], [4]) = 0 <0.000039>
curl: (7) Failed to connect to api.local port 8080: Connection timed out
nonblockingにした上で、Connectを一度だけ呼び、あとはpollを定期的に呼び続けている。
SYNの再送が裏側でおこなわれているが、詳細が気になるかたはこのあたりを。
https://github.com/KeiichiHirobe/tcp-keepalives#test-syn-sentpy
30秒後くらいに[ETIMEDOUT](Connection timed out)にてエラーを確認している。
プログラムにて確認
コマンドによる検証だけでは、確かめたいケースを検証できないことが多い。その場合は自分でコードを組んで検証するしかない。
https://blog.cloudflare.com/when-tcp-sockets-refuse-to-die/
というTCPの再送についてかなり詳しくかかれているブログがあり、とても素晴らしいのだが、その検証コードも素晴らしくGitHubにあがっている。
ここでは、それをforkして、説明を追加して整理したり、自分の確かめたかった様々なケースを追加して以下に公開してある。ひとつひとつ説明していく余裕はないので詳しくはそちらのREADMEを見て欲しい。
例
ひとつだけ例をあげる。
https://qiita.com/behiron/items/3719430e12cb770980f3
にて、「write時に、RSTの前にFINを受け取っていた場合EPIPE/SIGPIPEになる」という話を書いたのだがこれを検証する。
以下、GitHubにあげたコードと説明のほぼコピペになるが、あげておく。
import io
import os
import select
import socket
import time
import utils
port = 1
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM, 0)
s.bind(('127.0.0.1', port))
s.listen(16)
tcpdump = utils.tcpdump_start(port)
c = socket.socket(socket.AF_INET, socket.SOCK_STREAM, 0)
time.sleep(1)
utils.ss(port)
c.connect(('127.0.0.1', port))
time.sleep(1)
print("[c] client connect")
utils.ss(port)
x, _ = s.accept()
time.sleep(1)
print("[x] server accept")
utils.ss(port)
# for num in range(3):
# print("[x] send")
# c.send(b"hello world")
x.shutdown(socket.SHUT_WR)
time.sleep(1)
print("[x] server shutdown(SHUT_WR)")
utils.ss(port)
x.close()
time.sleep(1)
print("[x] server close socket")
utils.ss(port)
for num in range(3):
print("[x] send")
c.send(b"hello world")
time.sleep(1)
utils.ss(port)
print("#####just ss outputs from now#####")
time.sleep(1)
utils.ss(port)
time.sleep(1)
utils.ss(port)
time.sleep(1)
utils.ss(port)
以下を確かめることができた。
サーバはacceptして、shutdown(socket.SHUT_WR)するとFINがクライアントに飛ぶ。その後closeするが、何も行われない。
サーバのcloseが終わってからクライアントはデータを送る。
クライアントは、1度目のwrite時にサーバからRSTを受け取る。もちろんアプリケーションレベルだとそのことは知らずに普通に成功で返る。
クライアントは、2度目のwrite時に自分がFIN->RSTを受け取っていることに気づき、データを送る前に[EPIPE] Broken pipeでエラーになる。
以下はプログラムの出力である。
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 16 127.0.0.1:1 *:*
00:00:00.000000 IP 127.0.0.1.40482 > 127.0.0.1.1: Flags [S], seq 1820496075, win 65495, options [mss 65495,sackOK,TS val 2241891913 ecr 0,nop,wscale 7], length 0
00:00:00.000084 IP 127.0.0.1.1 > 127.0.0.1.40482: Flags [S.], seq 2642886490, ack 1820496076, win 65483, options [mss 65495,sackOK,TS val 2241891913 ecr 2241891913,nop,wscale 7], length 0
00:00:00.000123 IP 127.0.0.1.40482 > 127.0.0.1.1: Flags [.], ack 1, win 512, options [nop,nop,TS val 2241891913 ecr 2241891913], length 0
[c] client connect
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 1 16 127.0.0.1:1 *:*
ESTAB 0 0 127.0.0.1:40482 127.0.0.1:1
ESTAB 0 0 127.0.0.1:1 127.0.0.1:40482
[x] server accept
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 16 127.0.0.1:1 *:*
ESTAB 0 0 127.0.0.1:40482 127.0.0.1:1
ESTAB 0 0 127.0.0.1:1 127.0.0.1:40482
00:00:02.016320 IP 127.0.0.1.1 > 127.0.0.1.40482: Flags [F.], seq 1, ack 1, win 512, options [nop,nop,TS val 2241893929 ecr 2241891913], length 0
00:00:02.017333 IP 127.0.0.1.40482 > 127.0.0.1.1: Flags [.], ack 2, win 512, options [nop,nop,TS val 2241893930 ecr 2241893929], length 0
# shutdown(SHUT_WR)だけではFIN-WAIT-2のタイマーは起動していない。tcp_fin_timeoutによりtimerの秒数が変化することを確認ずみ。ちなみにshutdown(SHUT_RDWR)でも同様だったのでソケットをcloseしないとタイマーは起動しない模様
[x] server shutdown(SHUT_WR)
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 16 127.0.0.1:1 *:*
CLOSE-WAIT 1 0 127.0.0.1:40482 127.0.0.1:1
FIN-WAIT-2 0 0 127.0.0.1:1 127.0.0.1:40482
[x] server close socket
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 16 127.0.0.1:1 *:*
CLOSE-WAIT 1 0 127.0.0.1:40482 127.0.0.1:1
FIN-WAIT-2 0 0 127.0.0.1:1 127.0.0.1:40482 timer:(timewait,58sec,0)
[x] send
00:00:04.031169 IP 127.0.0.1.40482 > 127.0.0.1.1: Flags [P.], seq 1:12, ack 2, win 512, options [nop,nop,TS val 2241895944 ecr 2241893929], length 11
00:00:04.031223 IP 127.0.0.1.1 > 127.0.0.1.40482: Flags [R], seq 2642886492, win 0, length 0
# RSTを受け取るとクライアント、サーバ両方とも即時にssの出力から消える
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 16 127.0.0.1:1 *:*
# 2度目のsendで即時にエラー
[x] send
Traceback (most recent call last):
File "test-rst.py", line 49, in <module>
c.send(b"hello world")
BrokenPipeError: [Errno 32] Broken pipe
ちなみにこのコードを少し修正することで以下も検証している。
-
shutdown(SHUT_WR)->closeではなく、closeのみした場合はどうなるか？ -> 上記と全く変わらない。 -
shutdown(SHUT_WR)->closeではなく、shutdown(SHUT_RDWR)のみした場合はどうなるか？ -> 上記と全く変わらない。 -
shutdown(SHUT_WR)->closeではなく、shutdown(SHUT_WR)のみした場合はどうなるか？ -> FINを飛ばすだけなのでwriteは全て成功する(直感通り)。 -
shutdown(SHUT_WR)->closeではなく、shutdown(SHUT_RD)のみした場合はどうなるか？ -> writeは全て成功する。shutdown(socket.SHUT_RD)のみだとおそらくTCPの動作には影響を与えないと思われる? -
except Exception as e:にてwriteの例外を無視して処理を続行した場合どうなるか？ -> その後のwriteは同様に[EPIPE] Broken pipeにてエラー -
except Exception as e:にてwriteの例外を無視してreadした場合どうなるか？ -> その後のreadはEOFですぐ返る
まとめ
TCPの細かい挙動とシステムコールとの関係を知るためのツールとして、有用なコマンドとコード群を紹介した。コードを理解するのはやや面倒かもしれないが、一度理解してしまえば、いつでも検証できる環境とコードがあるのは強みになると思うので時間をかけて理解する価値があると思う。
筆者は、今回ブログを書くきっかけとなったCloudflareのブログ数個を読み込み、検証コード等書くなど気づいたら10~20時間くらいは費やしていたが、振り返ってもよかったのではと思っている。
-
パターンが多過ぎてとても書き切れない。確認したことはhttps://github.com/KeiichiHirobe/tcp-keepalives に少しまとめているので興味ある方はそちらをみてください。 ↩
-
https://blog.cloudflare.com/when-tcp-sockets-refuse-to-die/ をもとにまとめたり、検証コードを参考にプログラムを組んで筆者が検証したもの。WEB上だと情報がほぼないのでつい書きすぎてしまった ↩
-
WEB上だと、tcp_fin_timeoutで制御可能とあまりにもたくさん書かれているのが謎である。マニュアルを読んでもそのようには読めないし、検証しても制御できなかった。古いkernelはそういう挙動をしたのかもしれない? https://www.samir.ca/2010/12/01/tcp_fin_timeout-doesnt-control-time_wait.html によると、TCP_TIMEWAIT_LENにハードコーディングされているとのこと ↩
-
WEB上だと、ESTABLISHED前の状態数であるとあまりにもたくさん書かれているのが謎である。こちらもそうでないことは検証済みである。もしかしてssの前身のnetstatはそういう挙動をしたのかも？ ↩