CLOVER🍀

That was when it all began.

Linuxのbacklogについて調べてみる

これは、なにをしたくて書いたもの?

LinuxでTCPソケットをリッスンする時に使うシステムコールとして、listenがあります。

この時に使うbacklogについて、ちょっと知りたくなったので調べてみました。

manから見るbacklog

manのlistenシステムコールの説明から、まずは見てみます。

Man page of 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

RFC: 793 / Terminology

ちなみに、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の説明を見てみましょう。

Man page of 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

参考)

How TCP backlog works in Linux