これは、なにをしたくて書いたもの？
LinuxでTCPソケットをリッスンする時に使うシステムコールとして、listenがあります。
この時に使うbacklogについて、ちょっと知りたくなったので調べてみました。
manから見るbacklog
manのlistenシステムコールの説明から、まずは見てみます。
backlog 引き数は、 sockfd についての保留中の接続のキューの最大長を指定する。 キューがいっぱいの状態で接続要求が到着すると、クライアントは ECONNREFUSED というエラーを受け取る。下位層のプロトコルが再送信をサポート していれば、要求は無視され、これ以降の接続要求の再送信が成功するかもしれない。
接続キューの長さであり、かつ次の文章を読むと確立済みソケットであると言います。acceptが呼ばれるのを待っているソケット、みたいですね。
TCP ソケットでの backlog 引き数の振る舞いは Linux 2.2 で変更された。 現在ではこの引き数は、 受け付けられるのを待っている、 完全に 確立されたソケットのキューの長さを指定する。
また、backlogの指定はカーネルパラメーターsomaxconnの設定に制限されるようです、と。
backlog 引き数が /proc/sys/net/core/somaxconn の値よりも大きければ、 backlog の値は暗黙のうちにこの値に切り詰められる。 このファイルのデフォルト値は 128 である。 バージョン 2.4.5 以前のカーネルでは、この上限値は コード埋め込みの固定値 SOMAXCONN であり、その値は 128 であった。
確認してみたいこと
せっかくなので、このbacklogを小さな値に設定したサーバープログラムを起動し、backlogより大きな数の接続を行ってみて、どのようなことが
起こるのか確認してみましょう。
環境
今回の環境は、こちら。
$ lsb_release -a No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 18.04.2 LTS Release: 18.04 Codename: bionic $ uname -srvmpio Linux 4.15.0-54-generic #58-Ubuntu SMP Mon Jun 24 10:55:24 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
Ubuntu Linux 18.04 LTSで、カーネルのバージョンは4.15です。
manから見て、関連しそうなパラメーター。
$ sudo sysctl -a 2>&1 | grep -E 'somaxconn|tcp_max_syn_backlog|syncookie' net.core.somaxconn = 128 net.ipv4.tcp_max_syn_backlog = 512 net.ipv4.tcp_syncookies = 1
また、サーバープログラムにはPythonを使用します。
$ python3 -V Python 3.6.8
サーバープログラム
では、簡単なサーバープログラムを作成します。
silent_server.py
import socket import time from datetime import datetime host = '0.0.0.0' port = 8080 bind_address = (host, port) backlog_size = 2 with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as server_socket: server_socket.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) server_socket.bind(bind_address) server_socket.listen(backlog_size) print('[{}] Server startup'.format(datetime.now().strftime('%Y-%m-%d %H:%M:%S'))) try: client_socket, addr = server_socket.accept() remote_addr = client_socket.getpeername() print('[{}] - handle connection, start - {}'.format(datetime.now().strftime('%Y-%m-%d %H:%M:%S'), remote_addr)) with client_socket: while True: time.sleep(1) except KeyboardInterrupt: print('[{}] Server stop'.format(datetime.now().strftime('%Y-%m-%d %H:%M:%S')))
listen時のbacklog指定は2です。
backlog_size = 2
server_socket.listen(backlog_size)
また、ソケットを1度acceptしたら、それ以降なにもしないプログラムになっています。
try: client_socket, addr = server_socket.accept() remote_addr = client_socket.getpeername() print('[{}] - handle connection, start - {}'.format(datetime.now().strftime('%Y-%m-%d %H:%M:%S'), remote_addr)) with client_socket: while True: time.sleep(1)
要するに、最初のひとつしか接続できないサーバーです。
このサーバーに対して、複数の接続をして試してみましょう。
listenシステムコールが使われているかどうかを確認する
とはいえ、直接システムコールを呼んでいるわけでないので（Pythonを使っている）、ちゃんとlistenシステムコールが使われているかを
先に確認してみましょう。
straceで確認。
$ strace python3 silent_server.py 〜省略〜 listen(3, 2)
listenの第2引数に、指定したbacklogの値が設定されていることが確認できました。
また、例えばbacklogのサイズを10にしたりすると、こんな感じになります。
listen(3, 10)
サーバープログラムの起動とbacklogのサイズ確認
では、サーバープログラムを起動します。
$ python3 silent_server.py [2019-07-09 23:50:08] Server startup
この時、backlogに指定した値が反映されているかどうか、ssコマンドで確認してみましょう。リッスンしているソケットの情報を
見てみます。
$ ss -tnl State Recv-Q Send-Q Local Address:Port Peer Address:Port LISTEN 0 2 0.0.0.0:8080 0.0.0.0:*
この「Send-Q」がbacklogの数です。
先ほどと同じように、backlogの数を10にしたりすると、以下のようになります。
$ ss -tnl State Recv-Q Send-Q Local Address:Port Peer Address:Port LISTEN 0 10 0.0.0.0:8080 0.0.0.0:*
backlogのサイズが確認できたところで、プログラム中のbacklogは2に戻して、再度起動しなおします。
接続してみる
このサーバーに、接続してみます。今回はtelnetを使ってみましょう。「Connected to〜」と表示されるので、接続できたことがわかりやすいので。
$ telnet localhost 8080 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'.
ssコマンドで見てみます。「Recv-Q」は0です。
$ ss -tnl State Recv-Q Send-Q Local Address:Port Peer Address:Port LISTEN 0 2 0.0.0.0:8080 0.0.0.0:*
接続を3つ増やしてみます。
$ telnet localhost 8080 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. $ telnet localhost 8080 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. $ telnet localhost 8080 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'.
計4つのtelnetプロセスが接続している状態です。
ssコマンドで見てみます。
$ ss -tnl State Recv-Q Send-Q Local Address:Port Peer Address:Port LISTEN 3 2 0.0.0.0:8080 0.0.0.0:*
「Recv-Q」が3まで上がりました。3…？
※追記）
この＋1になる点について、確認してみました。
ssコマンドのRecv-Qが、backlog＋1の値まで上がるのはどうして？ - CLOVER🍀
ここで、さらに3つほどtelnetで接続してみます。
$ telnet localhost 8080 Trying 127.0.0.1... $ telnet localhost 8080 Trying 127.0.0.1... $ telnet localhost 8080 Trying 127.0.0.1...
いずれも、「Connected to〜」が表示されなくなりました。
リッスンしているソケットに対して、ssコマンドの結果には変化がありません。
$ ss -tnl State Recv-Q Send-Q Local Address:Port Peer Address:Port LISTEN 3 2 0.0.0.0:8080 0.0.0.0:*
この時、サーバー側から見たソケットの状態を見てみます。「ESTABLISH」が4つあります。
ss -tn | grep 8080 | grep -vE '8080 +$' ESTAB 0 0 127.0.0.1:8080 127.0.0.1:47220 ESTAB 0 0 127.0.0.1:8080 127.0.0.1:47214 ESTAB 0 0 127.0.0.1:8080 127.0.0.1:47218 ESTAB 0 0 127.0.0.1:8080 127.0.0.1:47222
telnetの動作状態とは一致します。backlogに入っている状態は、接続確立済み（ESTABLISH）ではあるけれど、acceptはまだ呼ばれていない状態、
と言えそうですね。
クライアント側のソケットから見てみると、「ESTABLISH」が4つ、「SYN-SENT」が3つあります。
$ ss -tn | grep 8080 | grep -E '8080 +$' SYN-SENT 0 1 127.0.0.1:47262 127.0.0.1:8080 ESTAB 0 0 127.0.0.1:47222 127.0.0.1:8080 SYN-SENT 0 1 127.0.0.1:47264 127.0.0.1:8080 ESTAB 0 0 127.0.0.1:47220 127.0.0.1:8080 SYN-SENT 0 1 127.0.0.1:47266 127.0.0.1:8080 ESTAB 0 0 127.0.0.1:47214 127.0.0.1:8080 ESTAB 0 0 127.0.0.1:47218 127.0.0.1:8080
ESTABLISHは接続確立、SYN-SENTは接続しにいった側（クライアント側）から見てSYNを送ったけれど、サーバー側からSYN／ACKが
返ってきていない状態ですね。
第16回 信頼性のある通信を実現するTCPプロトコル（3） (3/4)：基礎から学ぶWindowsネットワーク - ＠IT
ちなみに、SYN-SENTの状態のtelnetは、ずーっと放っておくとタイムアウトします。
$ telnet localhost 8080 Trying 127.0.0.1... telnet: Unable to connect to remote host: Connection timed out
接続できているものについては、そのままです。
$ telnet localhost 8080 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'.
SYN-SENTのものは、どうなっているのでしょう？SYN-SENTなtelnetプロセスがひとつの状態で、tcpdumpで確認してみました。
$ sudo tcpdump -i lo tcp port 8080 -n tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes 01:36:27.971473 IP 127.0.0.1.49728 > 127.0.0.1.8080: Flags [S], seq 1374582617, win 43690, options [mss 65495,sackOK,TS val 3648443592 ecr 0,nop,wscale 7], length 0 01:36:28.994888 IP 127.0.0.1.49728 > 127.0.0.1.8080: Flags [S], seq 1374582617, win 43690, options [mss 65495,sackOK,TS val 3648444615 ecr 0,nop,wscale 7], length 0 01:36:31.010974 IP 127.0.0.1.49728 > 127.0.0.1.8080: Flags [S], seq 1374582617, win 43690, options [mss 65495,sackOK,TS val 3648446631 ecr 0,nop,wscale 7], length 0 01:36:35.042911 IP 127.0.0.1.49728 > 127.0.0.1.8080: Flags [S], seq 1374582617, win 43690, options [mss 65495,sackOK,TS val 3648450663 ecr 0,nop,wscale 7], length 0 01:36:43.234975 IP 127.0.0.1.49728 > 127.0.0.1.8080: Flags [S], seq 1374582617, win 43690, options [mss 65495,sackOK,TS val 3648458855 ecr 0,nop,wscale 7], length 0 01:36:59.362981 IP 127.0.0.1.49728 > 127.0.0.1.8080: Flags [S], seq 1374582617, win 43690, options [mss 65495,sackOK,TS val 3648474983 ecr 0,nop,wscale 7], length 0 01:37:33.154941 IP 127.0.0.1.49728 > 127.0.0.1.8080: Flags [S], seq 1374582617, win 43690, options [mss 65495,sackOK,TS val 3648508775 ecr 0,nop,wscale 7], length 0
Flagsが「S」なので、SYNを再送していますね…。
なお、先ほどのプログラムではacceptした後になにもしないのですが、以下のようなものに変えて、リクエストを受け付けたらレスポンスを返して
クライアントを切断するようにした場合は、待たされていたtelnetプロセスが順次接続されていきました。
echo_server.py
import socket import time from datetime import datetime host = '0.0.0.0' port = 8080 bind_address = (host, port) backlog_size = 2 with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as server_socket: server_socket.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) server_socket.bind(bind_address) server_socket.listen(backlog_size) print('[{}] Server startup'.format(datetime.now().strftime('%Y-%m-%d %H:%M:%S'))) try: while True: client_socket, addr = server_socket.accept() remote_addr = client_socket.getpeername() print('[{}] - handle connection, start - {}'.format(datetime.now().strftime('%Y-%m-%d %H:%M:%S'), remote_addr)) with client_socket: data = client_socket.recv(1024) client_socket.send(b'Reply: ' + data) print('[{}] - handle connection, exit - {}'.format(datetime.now().strftime('%Y-%m-%d %H:%M:%S'), remote_addr)) except KeyboardInterrupt: print('[{}] Server stop'.format(datetime.now().strftime('%Y-%m-%d %H:%M:%S')))
再送中にサーバー側がacceptできたり、backlogが空いている状態になっていると、サーバー側と接続できます、と。
とはいえ、Linux的にはここまででも拒否したことになっていて、LINUX_MIB_LISTENOVERFLOWSというオーバーフローを表す
カウンター、そして接続をドロップしたことを表すLINUX_MIB_LISTENDROPSというカウンターが上がります。
これは、/proc/net/netstatのListenOverflows、ListenDropsという項目で確認できます。
$ cat /proc/net/netstat
ですが、catでは見づらい…netstatではキレイに見れるみたいですが、ssだとちゃんと見れないです…。
ここまでで、なんとなく挙動はわかりましたね。
今回の設定だと、クライアント側の挙動にも依存するのでしょうが、すぐにエラーで弾かれるというわけではない…？
もう1度、listenの説明を見てみましょう。
キューがいっぱいの状態で接続要求が到着すると、クライアントは ECONNREFUSED というエラーを受け取る。下位層のプロトコルが再送信をサポート していれば、要求は無視され、これ以降の接続要求の再送信が成功するかもしれない。
再送信のケースを今回は見た、ということになりますね。
backlogのサイズを大きくする
最後に、backlogのサイズを大きくしてプログラムを起動してみます。
backlog_size = 1024
ですが、backlogの値は128で頭打ちになります。
$ ss -tnl State Recv-Q Send-Q Local Address:Port Peer Address:Port LISTEN 0 128 0.0.0.0:8080 0.0.0.0:*
これは、カーネルパラメーターの「net.core.somaxconn」にbacklogの値が切り詰められた状態です。
なので、「net.core.somaxconn」の値を上げます。今回は1024にしてみましょう。
$ sudo sysctl -w net.core.somaxconn=1024 net.core.somaxconn = 1024
サーバープロセスを再起動すると、今度はbacklogの値が大きくなったことが確認できます。
$ ss -tnl State Recv-Q Send-Q Local Address:Port Peer Address:Port LISTEN 0 1024 0.0.0.0:8080 0.0.0.0:*
まとめ
Linuxのbacklogまわりの挙動を調べて、簡単な確認まで行ってみました。
backlogがacceptされる前のESTABLISHなソケットに対するキューであることや、backlogのサイズはカーネルパラメーターの影響を受けること、
backlogを超えた接続数を受け取った時はクライアントが再送したりする、ということが確認できました。
その他のTCPソケットの接続に関するパラメーターも、ちゃんと見ていかないといけない気がしますね。頑張りましょう。
関連しそうなLinuxカーネルのソースコード。
backlogの長さを設定したり、条件判定したりするところ。
https://github.com/torvalds/linux/blob/v4.15/net/ipv4/af_inet.c#L232
https://github.com/torvalds/linux/blob/v4.15/include/net/sock.h#L833-L836
backlogがいっぱいの場合の動作。
https://github.com/torvalds/linux/blob/v4.15/net/ipv4/tcp_ipv4.c#L1347-L1348
https://github.com/torvalds/linux/blob/v4.15/net/ipv4/tcp_ipv4.c#L1418-L1424
backlogがsomaxconnより少ない場合に、切り詰められる部分。
https://github.com/torvalds/linux/blob/v4.15/net/socket.c#L1480-L1481
ECONNREFUSEDとなる部分（今回は直接の関連はないというか、クライアント側の話）。
https://github.com/torvalds/linux/blob/v4.15/net/ipv4/tcp_input.c#L3977-L3979
参考）
