search

tempesta-tech / tempesta

All-in-one solution for high performance web content delivery and advanced protection against DDoS and web attacks
https://tempesta-tech.com/
GNU General Public License v2.0
618 stars 103 forks source link

Orphaned TLS sockets #1432

Closed krizhanovsky closed 3 years ago

krizhanovsky commented 4 years ago

Scope

Run Tempesta with enabled TLS in a VM and execut tls-perf against it from the host system as:

$ ./tls-perf -l 1000 -t 2 -T 30 192.168.100.4 9443

When the test is done, even after several minutes there are many ESTABLISHED connections:

ESTAB      0       0             192.168.100.4:443          192.168.100.1:41536                                                                                 
ESTAB      0       0             192.168.100.4:443          192.168.100.1:40694                                                                                 
ESTAB      0       0             192.168.100.4:443          192.168.100.1:41540                                                                                 
ESTAB      0       0             192.168.100.4:443          192.168.100.1:40524                                                                                 
ESTAB      0       0             192.168.100.4:443          192.168.100.1:46564
.....

I can easily reproduce the problem on current ak-secp256-perf branch. There are also many dmesg messages

TCP: too many orphaned sockets

Testing

No need any specific test, the problem is quite easy to observe.

krizhanovsky commented 3 years ago

Reproduced on current master as of 95dddf4768f2f6ad9e41fa64705c5904bdf09f13 inside 1-CPU VM with 1.5G RAM and net.ipv4.tcp_max_orphans = 32, tls-perf was ran from the host system. The problem definitely appeared with the same sysctl settings (https://github.com/tempesta-tech/tempesta/wiki/HTTP-transactions-performance#sysctl-settings), net.ipv4.tcp_max_orphans=32 in particular.

When tls-perf finishes or is terminated with ^C, I see many ESTABLISHED TLS sockets in ss. After some time the TCP: too many orphaned sockets is printed and many sockets are close, the rest are in FIN-WAIT-1 state.

TCP: too many orphaned sockets is printed by tcp_check_oom(), which is called by tcp_out_of_resources(), i.e. there is not enough memory (see also https://serverfault.com/questions/624911/what-does-tcp-too-many-orphaned-sockets-mean), tcp_close() and our ss_do_close(). The number of socket orphans are tracked by sk->sk_prot->orphan_count, which is increment in the same TCP and Tempesta closing routines and decremented in inet_csk_destroy_sock(). The main calls of the last function are TCP and Tempesta closing functions and the TCP keep-alive timer.

The problem isn't easy to reproduce, for example if I run tls-perf under strace, then I can't reproduce it.

The reason for ESTABLISHED sockets is actually that the server, Tempesta FW, doesn't received neither FIN nor RST from the client side: tcpdump for one of the ESTABLISHED socket after the end of the test looks as:

00:21:41.364712 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [S], seq 230404036, win 64240, options [mss 1460,sackOK,TS val 2283957448 ecr 0,nop,wscale 7], length 0
00:21:41.364716 IP 192.168.100.4.443 > 192.168.100.1.60188: Flags [S.], seq 4116888914, ack 230404037, win 28960, options [mss 1460,sackOK,TS val 3851384100 ecr 2283957448,nop,wscale 7], length 0
00:21:41.408213 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [.], ack 1, win 502, options [nop,nop,TS val 2283957549 ecr 3851384100], length 0
00:21:41.409114 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [P.], seq 1:117, ack 1, win 502, options [nop,nop,TS val 2283957550 ecr 3851384100], length 116
00:21:41.409226 IP 192.168.100.4.443 > 192.168.100.1.60188: Flags [.], ack 117, win 227, options [nop,nop,TS val 3851384145 ecr 2283957550], length 0
00:21:41.414260 IP 192.168.100.4.443 > 192.168.100.1.60188: Flags [P.], seq 1:959, ack 117, win 227, options [nop,nop,TS val 3851384150 ecr 2283957550], length 958
00:21:41.481147 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [.], ack 959, win 501, options [nop,nop,TS val 2283957599 ecr 3851384150], length 0
00:21:41.496272 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [P.], seq 117:243, ack 959, win 501, options [nop,nop,TS val 2283957608 ecr 3851384150], length 126
00:21:41.503345 IP 192.168.100.4.443 > 192.168.100.1.60188: Flags [P.], seq 959:1010, ack 243, win 227, options [nop,nop,TS val 3851384239 ecr 2283957608], length 51
00:21:41.562371 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [.], ack 1010, win 501, options [nop,nop,TS val 2283957688 ecr 3851384239], length 0
00:21:41.567096 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [R.], seq 243, ack 1010, win 501, options [nop,nop,TS val 2283957693 ecr 3851384239], length 0
00:21:49.069369 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [S], seq 318958285, win 64240, options [mss 1460,sackOK,TS val 2283965192 ecr 0,nop,wscale 7], length 0
00:21:49.069372 IP 192.168.100.4.443 > 192.168.100.1.60188: Flags [S.], seq 4237274169, ack 318958286, win 28960, options [mss 1460,sackOK,TS val 3851391807 ecr 2283965192,nop,wscale 7], length 0
00:21:49.141318 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [.], ack 1, win 502, options [nop,nop,TS val 2283965254 ecr 3851391807], length 0
00:21:49.143281 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [P.], seq 1:117, ack 1, win 502, options [nop,nop,TS val 2283965258 ecr 3851391807], length 116
00:21:49.143390 IP 192.168.100.4.443 > 192.168.100.1.60188: Flags [.], ack 117, win 227, options [nop,nop,TS val 3851391881 ecr 2283965258], length 0
00:21:49.146592 IP 192.168.100.4.443 > 192.168.100.1.60188: Flags [P.], seq 1:960, ack 117, win 227, options [nop,nop,TS val 3851391884 ecr 2283965258], length 959
00:21:49.219710 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [.], ack 960, win 501, options [nop,nop,TS val 2283965331 ecr 3851391884], length 0
00:21:49.242537 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [P.], seq 117:243, ack 960, win 501, options [nop,nop,TS val 2283965343 ecr 3851391884], length 126
00:21:49.254501 IP 192.168.100.4.443 > 192.168.100.1.60188: Flags [P.], seq 960:1011, ack 243, win 227, options [nop,nop,TS val 3851391992 ecr 2283965343], length 51
00:21:49.335958 IP 192.168.100.1.60188 > 192.168.100.4.443: Flags [.], ack 1011, win 501, options [nop,nop,TS val 2283965439 ecr 3851391992], length 0

Note that tls-perf finished normally. Meantime, at the middle of the benchmark session a typical trace looks like (collected on the host system):

00:30:51.466808 IP 192.168.100.4.443 > 192.168.100.1.38020: Flags [S.], seq 30633893, ack 304905526, win 28960, options [mss 1460,sackOK,TS val 3851934340 ecr 2284507592,nop,wscale 7], length 0
00:30:51.466820 IP 192.168.100.1.38020 > 192.168.100.4.443: Flags [.], ack 1, win 502, options [nop,nop,TS val 2284507677 ecr 3851934340], length 0
00:30:51.589720 IP 192.168.100.1.38020 > 192.168.100.4.443: Flags [P.], seq 1:117, ack 1, win 502, options [nop,nop,TS val 2284507800 ecr 3851934340], length 116
00:30:51.667132 IP 192.168.100.4.443 > 192.168.100.1.38020: Flags [.], ack 117, win 227, options [nop,nop,TS val 3851934541 ecr 2284507800], length 0
00:30:51.669012 IP 192.168.100.4.443 > 192.168.100.1.38020: Flags [P.], seq 1:959, ack 117, win 227, options [nop,nop,TS val 3851934542 ecr 2284507800], length 958
00:30:51.669018 IP 192.168.100.1.38020 > 192.168.100.4.443: Flags [.], ack 959, win 501, options [nop,nop,TS val 2284507879 ecr 3851934542], length 0
00:30:51.690734 IP 192.168.100.1.38020 > 192.168.100.4.443: Flags [P.], seq 117:243, ack 959, win 501, options [nop,nop,TS val 2284507901 ecr 3851934542], length 126
00:30:51.778263 IP 192.168.100.4.443 > 192.168.100.1.38020: Flags [P.], seq 959:1010, ack 243, win 227, options [nop,nop,TS val 3851934652 ecr 2284507901], length 51
00:30:51.778271 IP 192.168.100.1.38020 > 192.168.100.4.443: Flags [.], ack 1010, win 501, options [nop,nop,TS val 2284507988 ecr 3851934652], length 0
00:30:51.840368 IP 192.168.100.1.38020 > 192.168.100.4.443: Flags [R.], seq 243, ack 1010, win 501, options [nop,nop,TS val 2284508050 ecr 3851934652], length 0

I.e. tls-perf just silently kills a socket (there are some packet drops, but not so many as the problem sockets).

If I switch of the 0 LINGER in tls-perf, then the client terminates TCP connections with FIN and RST

00:52:40.464320 IP 192.168.100.1.39978 > 192.168.100.4.443: Flags [F.], seq 243, ack 1011, win 501, options [nop,nop,TS val 2285816674 ecr 3853243605], length 0
00:52:40.464325 IP 192.168.100.1.39978 > 192.168.100.4.443: Flags [R.], seq 244, ack 1011, win 501, options [nop,nop,TS val 2285816674 ecr 3853243605], length 0

The behavior is explained in https://stackoverflow.com/questions/3757289/when-is-tcp-option-so-linger-0-required