91877
ローカルホストでTCP接続と切断を繰り返すC++のクライアント/サーバーコードを書いて、実験していたところ、listen引数のbacklogを超えるリクエストの処理において、クライアントもサーバーも動いていない謎の1秒が挟まる現象が発生しました。この現象をご説明頂いた上で、対応方法を教えてください。

## 環境

Lubuntu 20.04 x86_64  
gcc 9.4.0  
C++17

## コード

```

    #include <iostream>
    #include <cstring>
    #include <chrono>
    #include <sstream>
    #include <iomanip>
    #include <arpa/inet.h>
    #include <sys/socket.h>
    #include <unistd.h>
    using namespace std;
    const string& appname(const string& s = string()) {
        static string _appname;
        if (! s.empty()) _appname = s;
        return _appname;
    }
    using namespace std::chrono;
    string timestr() {
        system_clock::time_point scp = system_clock::now();
        time_t t = system_clock::to_time_t(scp);
        tm lt;
        stringstream ss;
        ss << put_time(localtime_r(&t, &lt), "%Y/%m/%e %H:%M:%S") << "," << setw(3) << setfill('0') << duration_cast<milliseconds>(scp - system_clock::from_time_t(t)).count();
        return ss.str();
    }
    void log(ostream& out, const string& s) {out << timestr() << " " << appname() << ": " << s << endl;}
    void log(const string& s) {log(cout, s);}
    void log_error(const string& s) {log(cerr, s + ":" + strerror(errno));}
    #define LOG_ERROR() log_error(string(__FILE__) +  ":" + to_string(__LINE__))
    struct Sock {
        Sock(int sock): _sock{sock} {}
        ~Sock() {if (_sock >= 0) ::close(_sock);}
        operator int() {return _sock;}
        void close() {if (_sock >= 0) ::close(_sock); _sock = -1;}
    private:
        int _sock;
        Sock(){} Sock(const Sock&){} Sock& operator=(const Sock&){return *this;}
    };
    #define IF_ERROR_RETURN(cond) if (cond) {LOG_ERROR(); return;}
    int client(const int PORT = 8000, const size_t N = 0x100000) {
        auto func = [](auto id, int port) {
            string idhead{to_string(id) + ": "};
            auto log_with_id = [&](auto s){log(idhead + s);};
            Sock sock = socket(AF_INET, SOCK_STREAM, 0);
            IF_ERROR_RETURN(sock < 0);
            struct sockaddr_in addr;
            addr.sin_family = AF_INET;
            addr.sin_port = htons(port);
            IF_ERROR_RETURN(inet_pton(AF_INET, "127.0.0.1", &addr.sin_addr) <= 0);
            IF_ERROR_RETURN(connect(sock, (struct sockaddr*)&addr, sizeof(addr)) < 0);
            log_with_id("connection established");
            struct sockaddr_in local_address;
            socklen_t addr_size = sizeof(local_address);
            IF_ERROR_RETURN(getsockname(sock, (sockaddr*)(void*)&local_address, &addr_size) != 0);
            log_with_id("localport: " + to_string(ntohs(local_address.sin_port)));
            shutdown(sock, SHUT_WR);
            log_with_id("write shutdowned");
            shutdown(sock, SHUT_RD);
            log_with_id("recv shutdowned");
            sock.close();
        };
        for (int i = 0; i < N; ++i) {
            string s{to_string(i)};
            log(s + ": started");
            func(i, PORT);
            log(s + ": finished");
        }
        return 0;
    }
    #define IF_ERROR_BREAK(cond) if (cond) {LOG_ERROR(); break;}
    void server(const int PORT = 8000) {
        auto log_server = [](const string s) {log(string("server: ") + s);};
        struct sockaddr_in addr;
        struct sockaddr_in client;
        int sock;
        Sock serverSock = socket(AF_INET, SOCK_STREAM, 0);
        IF_ERROR_RETURN(serverSock < 0);
        addr.sin_family = AF_INET;
        addr.sin_port = htons(PORT);
        addr.sin_addr.s_addr = INADDR_ANY;
        IF_ERROR_RETURN(bind(serverSock, (struct sockaddr *)&addr, sizeof(addr)) < 0);
        IF_ERROR_RETURN(listen(serverSock, 5) < 0);
        while (true) {
            socklen_t len = sizeof(client);
            Sock sock = accept(serverSock, (struct sockaddr *)&client, &len);
            IF_ERROR_BREAK(sock < 0);
            log_server("remoteport: " + to_string(ntohs(client.sin_port)));
            char buff[4096];
            ssize_t readlen = read(sock, buff, sizeof(buff));
            IF_ERROR_BREAK(readlen < 0);
            if (readlen != 0) log_server("read!!! not empty!!!");
            sock.close();
            log_server("closed");
        }
        serverSock.close();
    }
    int main(int argc, char* argv[], char* envp[]) {
        appname(argv[0]);
        if (argc > 1 && string(argv[1]) == "--server") {server(); return 0;}
        else {return client();}
    }
    
```

## 確認方法

以下のスクリプトを実行してログを取る

```

    trap 'pkill -P $$' INT
    ./maxbacklog_time --server&
    server=$!
    ./maxbacklog_time
    kill $server
    
```

## ログ

以下のように、クライアント(225)が何故か1秒ほど待たされている。

```

    ...
    2022/10/27 18:44:31,859 ./maxbacklog_time: server: remoteport: 35178
    ...
    2022/10/27 18:44:31,859 ./maxbacklog_time: 221: localport: 35200
    ...
    2022/10/27 18:44:31,865 ./maxbacklog_time: 222: localport: 35206
    ...
    2022/10/27 18:44:31,865 ./maxbacklog_time: 223: localport: 35222
    ...
    2022/10/27 18:44:31,865 ./maxbacklog_time: 224: localport: 35232
    ...
    2022/10/27 18:44:31,865 ./maxbacklog_time: 224: finished
    2022/10/27 18:44:31,865 ./maxbacklog_time: 225: started
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: closed
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: remoteport: 35186
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: closed
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: remoteport: 35196
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: closed
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: remoteport: 35200
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: closed
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: remoteport: 35206
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: closed
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: remoteport: 35222
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: closed
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: remoteport: 35232
    2022/10/27 18:44:31,867 ./maxbacklog_time: server: closed
    2022/10/27 18:44:32,879 ./maxbacklog_time: 225: connection established
    ...
    
```

## 質問

現象をご説明頂き、同期I/O＆シングルスレッド＆(アプリケーション層での)送受信データの変更なしに、謎の1秒を挟まない方法があれば教えてください。
CC BY-SA 4.0
2022-10-27T10:22:18.727
91865
2022-10-30T10:16:28.120
2022-10-27T16:14:47.960
54957
54957
question
c++ network tcp
backlogを超えるリクエストで謎の1秒待ち
## 現象の説明

### パケットログ

```

    18:44:31.865734 IP localhost.35238 > localhost.8000: Flags [S], seq 2050667274, win 65495, options [mss 65495,sackOK,TS val 2726005063 ecr 0,nop,wscale 7], length 0
    18:44:31.867175 IP localhost.8000 > localhost.35186: Flags [F.], seq 1, ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005056], length 0
    18:44:31.867183 IP localhost.35186 > localhost.8000: Flags [.], ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005064], length 0
    18:44:31.867284 IP localhost.8000 > localhost.35196: Flags [F.], seq 1, ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005056], length 0
    18:44:31.867290 IP localhost.35196 > localhost.8000: Flags [.], ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005064], length 0
    18:44:31.867383 IP localhost.8000 > localhost.35200: Flags [F.], seq 1, ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005062], length 0
    18:44:31.867393 IP localhost.35200 > localhost.8000: Flags [.], ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005064], length 0
    18:44:31.867455 IP localhost.8000 > localhost.35206: Flags [F.], seq 1, ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005063], length 0
    18:44:31.867479 IP localhost.35206 > localhost.8000: Flags [.], ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005064], length 0
    18:44:31.867541 IP localhost.8000 > localhost.35222: Flags [F.], seq 1, ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005063], length 0
    18:44:31.867566 IP localhost.35222 > localhost.8000: Flags [.], ack 2, win 512, options [nop,nop,TS val 2726005064 ecr 2726005064], length 0
    18:44:31.867628 IP localhost.8000 > localhost.35232: Flags [F.], seq 1, ack 2, win 512, options [nop,nop,TS val 2726005065 ecr 2726005063], length 0
    18:44:31.867651 IP localhost.35232 > localhost.8000: Flags [.], ack 2, win 512, options [nop,nop,TS val 2726005065 ecr 2726005065], length 0
    18:44:32.879272 IP localhost.35238 > localhost.8000: Flags [S], seq 2050667274, win 65495, options [mss 65495,sackOK,TS val 2726006076 ecr 0,nop,wscale 7], length 0
    
```

一言で言えば謎の1秒はLinuxのSYNパケット再送時間です。

### ログにサーバーとクライアントが交互に現れない理由

同期I/Oとシングルスレッドを使用し、事前に通信状況を確認せず読み書きしているのに、サーバーとクライアントが交互に現れないのは、クライアントが接続要求した際に出るSYNパケットをサーバーが受信すると、acceptが戻る前にTCPスタックがSYN-
ACKを返しているためです。

<http://arthurchiao.art/blog/tcp-listen-a-tale-of-two-queues/>

クライアント側はSYN-
ACKを受け取ると、ACKを返しつつconnectが戻るため、そのまま切断できて次の接続処理を開始できます。そのため、タイミングによっては、サーバーがacceptを処理する前に複数の接続/切断処理を実行できるわけです。

### 謎の1秒の正体とは

サーバーではacceptキューがbacklog分貯まると、SYNパケットがそのまま捨てられるため、クライアントにはSYN-
ACKが返りません。そのため、クライアント側からはSYNパケットの再送が1秒後に始まります。つまりクライアント側がSYNパケットが捨てられたことを検出するのに1秒かかるというわけです。

## 対応方法

### 修正

~~acceptより前にSYN-
ACKが返る以上、サーバーとクライアントが交互に動く保証はなく、そうなるとバックログ分acceptキューに溜まっていくことも抑えられません。アプリケーション層の授受データを変えない限り、対応は不可能に見えます。~~  
clientが送信側のshutdownの後、readすれば次のコネクションを張りにいかないので、交互に動かすことができました。失念しててすみません。

```

    @@ -53,6 +53,10 @@ int client(const int PORT = 8000, const
             log_with_id("localport: " + to_string(ntohs(local_address.sin_port)));
             shutdown(sock, SHUT_WR);
             log_with_id("write shutdowned");
    +        char buff[4096];
    +        ssize_t readlen = read(sock, buff, sizeof(buff));
    +        IF_ERROR_RETURN(readlen < 0);
    +        if (readlen != 0) log_with_id("read!!! not empty!!!");
             shutdown(sock, SHUT_RD);
             log_with_id("recv shutdowned");
                    sock.close();
    
```

## 補足

サーバー→クライアントに1バイトだけ通信するとサーバーとクライアントが交互に動き、SYN再送は発生しません。

### 追記

client側でreadをすることで通信データを加える必要がないことが分かりました。この補足は不要です。

```

    @@ -51,6 +51,10 @@ int client(const int PORT = 8000, const
             socklen_t addr_size = sizeof(local_address);
             IF_ERROR_RETURN(getsockname(sock, (sockaddr*)(void*)&local_address, &addr_size) != 0);
             log_with_id("localport: " + to_string(ntohs(local_address.sin_port)));
    +        char buffer;
    +        ssize_t len = read(sock, &buffer, sizeof(buffer));
    +        IF_ERROR_RETURN(len < 0);
    +        if (len == 0) {log_with_id("unexpected EOF!!!");}
             shutdown(sock, SHUT_WR);
             log_with_id("write shutdowned");
             shutdown(sock, SHUT_RD);
    @@ -83,7 +87,9 @@ void server(const int PORT = 8000) {
             Sock sock = accept(serverSock, (struct sockaddr *)&client, &len);
             IF_ERROR_BREAK(sock < 0);
             log_server("remoteport: " + to_string(ntohs(client.sin_port)));
    -        char buff[4096];
    +        char buff[4096]; buff[0] = 0;
    +        IF_ERROR_BREAK(write(sock, buff, 1) < 0);
    +        log_server("wrote 1byte");
             ssize_t readlen = read(sock, buff, sizeof(buff));
             IF_ERROR_BREAK(readlen < 0);
             if (readlen != 0) log_server("read!!! not empty!!!");
    
```
CC BY-SA 4.0
2022-10-28T09:21:44.947
91877
2022-10-30T10:16:28.120
2022-10-30T10:16:28.120
54957
54957
91865
answer