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, <), "%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分経たずに使われる原因を教えてください。