1

SO_REUSEADDRもしてないのにTIME_WAITなポートが1分経たずに使える原因が分かりません。
原因が分かりましたら教えてください。

現象の説明

環境

Lubuntu 20.04 x86_64
gcc 9.4.0
C++17

再現コード

#include <thread>
#include <vector>
#include <iostream>
#include <cstring>
#include <chrono>
#include <sstream>
#include <iomanip>
#include <map>
#include <fstream>
#include <arpa/inet.h>
#include <sys/socket.h>
#include <unistd.h>
#include "magic_enum.hpp" // https://github.com/Neargye/magic_enum/releases/download/v0.8.1/magic_enum.hpp
using namespace std;
enum TCPSTATUS {
    UNKNOWN, ESTABLISHED, SYN_SENT, SYN_RECV, FIN_WAIT1, FIN_WAIT2, TIME_WAIT, CLOSE, CLOSE_WAIT, LAST_ACK, LISTEN, CLOSING,
};
struct Sock {
    Sock(int sock): _sock{sock} {}
    ~Sock() {if (_sock >= 0) ::close(_sock);}
    operator int() const {return _sock;}
    void close() {if (_sock >= 0) ::close(_sock); _sock = -1;}
private:
    int _sock;
    Sock(){} Sock(const Sock&){} Sock& operator=(const Sock&){return *this;}
};
map<string, TCPSTATUS> table = []{
    decltype(table) t;
    for (auto status: magic_enum::enum_values<TCPSTATUS>()) {
        stringstream ss;
        ss << setw(2) << setfill('0') << magic_enum::enum_integer(status);
        t[ss.str()] = status;
    }
    return t;
}();
string hexstring_upper(unsigned int num, int width) {
    stringstream ss;
    ss << hex << setw(width) << setfill('0') << uppercase << num;
    return ss.str();
}
TCPSTATUS get_tcpstatus(const sockaddr_in& local, const sockaddr_in& remote) {
    string local_string = hexstring_upper(local.sin_addr.s_addr,8) + ":" + hexstring_upper(htons(local.sin_port), 4);
    string remote_string = hexstring_upper(remote.sin_addr.s_addr,8) + ":" + hexstring_upper(htons(remote.sin_port), 4);
    ifstream proctcp("/proc/net/tcp");
    string line;
    getline(proctcp, line); // skip header
    while (getline(proctcp, line)) {
        stringstream ss(line);
        string column;
        enum state {nothing, local_matched, remote_matched} s = nothing;
        for (int i = 0; i < 4 && getline(ss, column, ' ');) {
            if (column.length() == 0) continue;
            if (s == nothing && i == 1) {
                if (column == local_string) {s = local_matched;} else {break;}
            }
            else if (s == local_matched && i == 2) {
                if (column == remote_string) {s = remote_matched;} else {break;}
            } else if (s == remote_matched && i == 3) {
                return table[column];
            }
            ++i;
        }
    }
    return UNKNOWN;
}
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__))
#define IF_ERROR_RETURN(cond) if (cond) {LOG_ERROR(); return;}
int client(bool dont_read_proc = false, const int PORT = 8000, const size_t N = 0x100000) {
    auto func = [](auto id, int port, bool dont_read_proc) {
        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)));
        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);
        log_with_id("recv shutdowned");
        if (! dont_read_proc) {
            TCPSTATUS status;
            while ((status = get_tcpstatus(local_address, addr)) == ESTABLISHED);
            switch (status) {
                case FIN_WAIT1: case FIN_WAIT2: case CLOSING: case TIME_WAIT: break;
                default: log_with_id("NOT TIME_WAIT!!!(" + string(magic_enum::enum_name<TCPSTATUS>(status)) + ")"); break;
            }
        }
        sock.close();
    };
    for (int i = 0; i < N; ++i) {
        string s{to_string(i)};
        log(s + ": started");
        func(i, PORT, dont_read_proc);
        log(s + ": finished");
    }
    return 0;
}
#define IF_ERROR_BREAK(cond) if (cond) {LOG_ERROR(); break;}
void server(bool dont_read_proc = false, 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]; 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!!!");
        if (! dont_read_proc) {
            TCPSTATUS status;
            while ((status = get_tcpstatus(addr, client)) == ESTABLISHED);
            switch (status) {
                case FIN_WAIT1: case FIN_WAIT2: case CLOSING: case TIME_WAIT:
                    log_server("TIME_WAIT!!!(" + string(magic_enum::enum_name<TCPSTATUS>(status)) + ")");
                    break;
                default:
                    break;
            }
        }
        sock.close();
        log_server("closed");
        log_server("finished");
    }
    serverSock.close();
}
int main(int argc, char* argv[], char* envp[]) {
    appname(argv[0]);
    if (argc > 1 && string(argv[1]) == "--server") {server(argc > 2 && string(argv[2]) == "--dontreadproc"); return 0;}
    else {
        return client(argc > 1 && string(argv[1]) == "--dontreadproc");
    }
}

再現方法

以下のコードを実行する

trap 'pkill -P $$' INT
./tcp_timewait --server --dontreadproc&
server=$!
./tcp_timewait --dontreadproc
kill $server

現象

ログ出力から、実行時間を取得する
2022/10/28 18:48:22,266 ~ 2022/10/28 18:54:00,694
→00:05:38,428
この間に接続は1048576回行われているため、1分当たり185902回となり、65536を大幅に超えている(アプリケーションから使用可能なポートの数は最大でも28232個)。

何が問題なのか?

TCPでは能動的に切断した側がTIME_WAITになるため、1分は同じポートが使えないはずだと思っていましたが、setsockoptも使ってないのにエラーになりません。

調査したこと

ssによる秒単位のデータ取得

先の実験を以下のスクリプトを流しながら実施しました。

while sleep 1;date;do ss -atn | grep 8000 | awk '{print $1;}' | sort | uniq -c;done | tee connection.log

結果は以下のとおりで、およそ14000程度のTIME-WAITが常時発生している状態でした。

...
2022年 10月 28日 金曜日 18:52:39 JST
      1 ESTAB
      1 LISTEN
  14113 TIME-WAIT
2022年 10月 28日 金曜日 18:52:40 JST
      1 LISTEN
      1 SYN-SENT
  14112 TIME-WAIT
2022年 10月 28日 金曜日 18:52:41 JST
      2 ESTAB
      1 LISTEN
  14111 TIME-WAIT
...

使用直後のポートのTCP状態判定

クライアント側が意図したとおりにTIME_WAITになるかどうかを確認する仕込みコードを動かしてログを確認しました。

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

出力したログをgrepした結果が以下です。

$ grep TIME_WAIT test_timewait.sh.log 
2022/10/28 19:58:57,011 ./tcp_timewait: 313851: NOT TIME_WAIT!!!(UNKNOWN)
2022/10/28 20:00:27,009 ./tcp_timewait: 321427: NOT TIME_WAIT!!!(UNKNOWN)
2022/10/28 20:21:59,011 ./tcp_timewait: 428676: NOT TIME_WAIT!!!(UNKNOWN)
2022/10/28 20:22:30,014 ./tcp_timewait: 431343: NOT TIME_WAIT!!!(UNKNOWN)
2022/10/28 20:35:07,006 ./tcp_timewait: 493355: NOT TIME_WAIT!!!(UNKNOWN)
2022/10/28 20:55:37,851 ./tcp_timewait: 592666: NOT TIME_WAIT!!!(UNKNOWN)
2022/10/28 20:57:50,018 ./tcp_timewait: 602860: NOT TIME_WAIT!!!(UNKNOWN)
2022/10/28 21:02:47,017 ./tcp_timewait: 626236: NOT TIME_WAIT!!!(UNKNOWN)
2022/10/28 21:29:17,015 ./tcp_timewait: 752720: NOT TIME_WAIT!!!(UNKNOWN)
$

一応9行分状態取得に失敗したケースが抽出されています。しかし、それ以外のほとんど全ては意図したとおりの状態だったということで、状態遷移は(ほぼ)想定どおりであることが確認されました。

現状の調査状況のまとめ

ほぼ意図したとおりの状態遷移が行われていますが、14000程度の接続時になぜかTIME_WAITポートが再利用されるような挙動を示しています。

質問

現象をご説明頂き、TIME_WAITなポートが1分経たずに使われる原因を教えてください。

1 件の回答 1

0
$ sysctl  net.ipv4.tcp_tw_reuse
net.ipv4.tcp_tw_reuse = 2
$

https://www.kernel.org/doc/Documentation/networking/ip-sysctl.txt

tcp_tw_reuse - INTEGER
Enable reuse of TIME-WAIT sockets for new connections when it is
safe from protocol viewpoint.
0 - disable
1 - global enable
2 - enable for loopback traffic only
It should not be changed without advice/request of technical
experts.
Default: 2

追記

これを0にセットすると、14000付近で止まっていたTIME_WAIT数が16384まで上昇します。しかし、相変わらずconnectは失敗しません。

追記2

$ sysctl net.ipv4.tcp_max_tw_buckets
net.ipv4.tcp_max_tw_buckets = 16384
$
https://www.kernel.org/doc/Documentation/networking/ip-sysctl.txt

tcp_max_tw_buckets - INTEGER
Maximal number of timewait sockets held by system simultaneously.
If this number is exceeded time-wait socket is immediately destroyed
and warning is printed. This limit exists only to prevent
simple DoS attacks, you must not lower the limit artificially,
but rather increase it (probably, after increasing installed memory),
if network conditions require more than default value.

この質問に回答するには、ログインする必要があります。

求めていた回答ではありませんか? のタグが付いた他の質問を参照する。