Hi all,
I did some ebpf sockmap test using demo from https://github.com/ArthurChiao/socket-acceleration-with-ebpf,
that using a BPF_PROG_TYPE_SOCK_OPS prog to store local passive/active established socket in a BPF_MAP_TYPE_SOCKHASH map,
and then use a BPF_PROG_TYPE_SK_MSG prog to redirect messages between two local sockets.
And if I use nginx as a proxy, webfsd as a upstream server, like this: curl <--> nginx(192.168.174.128:80)<-->(webfsd)127.0.0.1:8090,
it highly download failed, curl only recv partial data and was stuck.
From nginx debug log(see the attached file), it seems nginx get an EPOLLRDHUP event before read all data from kernel buffer.
I think it happened like this:
1)kernel send FIN after webfsd send out all data, and for nginx view, when kernel recv the FIN, will shutdown recv:
tcp_fin(): sk->sk_shutdown |= RCV_SHUTDOWN;
2)and nginx will get an EPOLLRDHUP event:
tcp_poll():
if (sk->sk_shutdown & RCV_SHUTDOWN)
mask |= EPOLLIN | EPOLLRDNORM | EPOLLRDHUP;
3)so nginx will not read all data that already in kernel recv buffer?
Is this a kernel ebpf/tcp BUG? [root@localhost bpf]# curl -vo /dev/null http://192.168.174.128:80/
* About to connect() to 192.168.174.128 port 80 (#0)
* Trying 192.168.174.128...
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Connected to 192.168.174.128 (192.168.174.128) port 80 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.29.0
> Host: 192.168.174.128
> Accept: */*
>
< HTTP/1.1 200 OK
< Server: nginx/1.20.1
< Date: Tue, 12 Apr 2022 07:34:37 GMT
< Content-Type: text/html
< Content-Length: 8948
< Connection: keep-alive
< Accept-Ranges: bytes
< Last-Modified: Fri, 01 Apr 2022 09:53:06 GMT
<
{ [data not shown]
89 8948 89 7982 0 0 3544 0 0:00:02 0:00:02 --:--:-- 3544
=====nginx log=========
2022/04/11 15:32:23 [debug] 4047#4047: accept on 0.0.0.0:80, ready: 0
2022/04/11 15:32:23 [debug] 4047#4047: posix_memalign: 000055C1426FDA60:512 @16
2022/04/11 15:32:23 [debug] 4047#4047: *45 accept: 192.168.174.128:61828 fd:3
2022/04/11 15:32:23 [debug] 4047#4047: *45 event timer add: 3: 60000:4628470
2022/04/11 15:32:23 [debug] 4047#4047: *45 reusable connection: 1
2022/04/11 15:32:23 [debug] 4047#4047: *45 epoll add event: fd:3 op:1 ev:80002001
2022/04/11 15:32:23 [debug] 4047#4047: *45 http wait request handler
2022/04/11 15:32:23 [debug] 4047#4047: *45 malloc: 000055C1426FDC70:1024
2022/04/11 15:32:23 [debug] 4047#4047: *45 recv: eof:0, avail:-1
2022/04/11 15:32:23 [debug] 4047#4047: *45 recv: fd:3 79 of 1024
2022/04/11 15:32:23 [debug] 4047#4047: *45 reusable connection: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 posix_memalign: 000055C1426F0C10:4096 @16
2022/04/11 15:32:23 [debug] 4047#4047: *45 http process request line
2022/04/11 15:32:23 [debug] 4047#4047: *45 http request line: "GET / HTTP/1.1"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http uri: "/"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http args: ""
2022/04/11 15:32:23 [debug] 4047#4047: *45 http exten: ""
2022/04/11 15:32:23 [debug] 4047#4047: *45 posix_memalign: 000055C1426B5BB0:4096 @16
2022/04/11 15:32:23 [debug] 4047#4047: *45 http process request header line
2022/04/11 15:32:23 [debug] 4047#4047: *45 http header: "User-Agent: curl/7.29.0"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http header: "Host: 192.168.174.128"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http header: "Accept: */*"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http header done
2022/04/11 15:32:23 [debug] 4047#4047: *45 event timer del: 3: 4628470
2022/04/11 15:32:23 [debug] 4047#4047: *45 generic phase: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 rewrite phase: 1
2022/04/11 15:32:23 [debug] 4047#4047: *45 test location: "/"
2022/04/11 15:32:23 [debug] 4047#4047: *45 using configuration "/"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http cl:-1 max:1048576
2022/04/11 15:32:23 [debug] 4047#4047: *45 rewrite phase: 3
2022/04/11 15:32:23 [debug] 4047#4047: *45 post rewrite phase: 4
2022/04/11 15:32:23 [debug] 4047#4047: *45 generic phase: 5
2022/04/11 15:32:23 [debug] 4047#4047: *45 generic phase: 6
2022/04/11 15:32:23 [debug] 4047#4047: *45 generic phase: 7
2022/04/11 15:32:23 [debug] 4047#4047: *45 generic phase: 8
2022/04/11 15:32:23 [debug] 4047#4047: *45 access phase: 9
2022/04/11 15:32:23 [debug] 4047#4047: *45 access phase: 10
2022/04/11 15:32:23 [debug] 4047#4047: *45 access phase: 11
2022/04/11 15:32:23 [debug] 4047#4047: *45 post access phase: 12
2022/04/11 15:32:23 [debug] 4047#4047: *45 generic phase: 13
2022/04/11 15:32:23 [debug] 4047#4047: *45 generic phase: 14
2022/04/11 15:32:23 [debug] 4047#4047: *45 http init upstream, client timer: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 epoll add event: fd:3 op:3 ev:80002005
2022/04/11 15:32:23 [debug] 4047#4047: *45 http script copy: "Host"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http script var: "127.0.0.1:8090"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http script copy: "Connection"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http script copy: "close"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http script copy: ""
2022/04/11 15:32:23 [debug] 4047#4047: *45 http script copy: ""
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "User-Agent: curl/7.29.0"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "Accept: */*"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header:
"GET / HTTP/1.0
Host: 127.0.0.1:8090
Connection: close
User-Agent: curl/7.29.0
Accept: */*
"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http cleanup add: 000055C1426B64E0
2022/04/11 15:32:23 [debug] 4047#4047: *45 get rr peer, try: 1
2022/04/11 15:32:23 [debug] 4047#4047: *45 stream socket 4
2022/04/11 15:32:23 [debug] 4047#4047: *45 epoll add connection: fd:4 ev:80002005
2022/04/11 15:32:23 [debug] 4047#4047: *45 connect to 127.0.0.1:8090, fd:4 #46
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream connect: -2
2022/04/11 15:32:23 [debug] 4047#4047: *45 posix_memalign: 000055C1426AC6D0:128 @16
2022/04/11 15:32:23 [debug] 4047#4047: *45 event timer add: 4: 60000:4628470
2022/04/11 15:32:23 [debug] 4047#4047: *45 http finalize request: -4, "/?" a:1, c:2
2022/04/11 15:32:23 [debug] 4047#4047: *45 http request count:2 blk:0
2022/04/11 15:32:23 [debug] 4047#4047: *45 http run request: "/?"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream check client, write event:1, "/"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream request: "/?"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream send request handler
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream send request
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream send request body
2022/04/11 15:32:23 [debug] 4047#4047: *45 chain writer buf fl:1 s:97
2022/04/11 15:32:23 [debug] 4047#4047: *45 chain writer in: 000055C1426B6520
2022/04/11 15:32:23 [debug] 4047#4047: *45 writev: 97 of 97
2022/04/11 15:32:23 [debug] 4047#4047: *45 chain writer out: 0000000000000000
2022/04/11 15:32:23 [debug] 4047#4047: *45 event timer del: 4: 4628470
2022/04/11 15:32:23 [debug] 4047#4047: *45 event timer add: 4: 60000:4628470
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream request: "/?"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream process header
2022/04/11 15:32:23 [debug] 4047#4047: *45 malloc: 000055C1426E2330:4096
2022/04/11 15:32:23 [debug] 4047#4047: *45 recv: eof:1, avail:-1
2022/04/11 15:32:23 [debug] 4047#4047: *45 recv: fd:4 4096 of 4096
2022/04/11 15:32:23 [debug] 4047#4047: *45 recv: avail:0
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy status 200 "200 OK"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "Server: webfs/1.21"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "Connection: Close"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "Accept-Ranges: bytes"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "Content-Type: text/html"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "Content-Length: 8948"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "Last-Modified: Fri, 01 Apr 2022 09:53:06 GMT"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header: "Date: Mon, 11 Apr 2022 07:32:23 GMT"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy header done
2022/04/11 15:32:23 [debug] 4047#4047: *45 HTTP/1.1 200 OK
Server: nginx/1.20.1
Date: Mon, 11 Apr 2022 07:32:23 GMT
Content-Type: text/html
Content-Length: 8948
Connection: keep-alive
Accept-Ranges: bytes
Last-Modified: Fri, 01 Apr 2022 09:53:06 GMT
2022/04/11 15:32:23 [debug] 4047#4047: *45 write new buf t:1 f:0 000055C1426B6870, pos 000055C1426B6870, size: 217 file: 0, size: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 http write filter: l:0 f:0 s:217
2022/04/11 15:32:23 [debug] 4047#4047: *45 http cacheable: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 http proxy filter init s:200 h:0 c:0 l:8948
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream process upstream
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe read upstream: 1
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe preread: 3886
2022/04/11 15:32:23 [debug] 4047#4047: *45 input buf #0
2022/04/11 15:32:23 [debug] 4047#4047: *45 malloc: 000055C1426AF3A0:4096
2022/04/11 15:32:23 [debug] 4047#4047: *45 readv: eof:1, avail:0
2022/04/11 15:32:23 [debug] 4047#4047: *45 readv: 1, last:4096
2022/04/11 15:32:23 [debug] 4047#4047: *45 readv: avail:0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe recv chain: 4096
2022/04/11 15:32:23 [debug] 4047#4047: *45 input buf #1
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe buf in s:1 t:1 f:0 000055C1426E2330, pos 000055C1426E2402, size: 3886 file: 0, size: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe buf in s:1 t:1 f:0 000055C1426AF3A0, pos 000055C1426AF3A0, size: 4096 file: 0, size: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe length: 966 // = 8948 - 3886 - 4096
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe write downstream: 1
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe write busy: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe write buf ls:1 000055C1426E2402 3886
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe write buf ls:1 000055C1426AF3A0 4096
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe write: out:000055C1426B6A88, f:0
2022/04/11 15:32:23 [debug] 4047#4047: *45 http output filter "/?"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http copy filter: "/?"
2022/04/11 15:32:23 [debug] 4047#4047: *45 posix_memalign: 000055C1426B03B0:4096 @16
2022/04/11 15:32:23 [debug] 4047#4047: *45 http postpone filter "/?" 000055C1426B6A78
2022/04/11 15:32:23 [debug] 4047#4047: *45 write old buf t:1 f:0 000055C1426B6870, pos 000055C1426B6870, size: 217 file: 0, size: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 write new buf t:1 f:0 000055C1426E2330, pos 000055C1426E2402, size: 3886 file: 0, size: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 write new buf t:1 f:0 000055C1426AF3A0, pos 000055C1426AF3A0, size: 4096 file: 0, size: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 http write filter: l:0 f:1 s:8199
2022/04/11 15:32:23 [debug] 4047#4047: *45 http write filter limit 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 writev: 8199 of 8199
2022/04/11 15:32:23 [debug] 4047#4047: *45 http write filter 0000000000000000
2022/04/11 15:32:23 [debug] 4047#4047: *45 http copy filter: 0 "/?"
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe write busy: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe write: out:0000000000000000, f:0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe read upstream: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe buf free s:0 t:1 f:0 000055C1426E2330, pos 000055C1426E2330, size: 0 file: 0, size: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe buf free s:0 t:1 f:0 000055C1426AF3A0, pos 000055C1426AF3A0, size: 0 file: 0, size: 0
2022/04/11 15:32:23 [debug] 4047#4047: *45 pipe length: 966
2022/04/11 15:32:23 [debug] 4047#4047: *45 event timer: 4, old: 4628470, new: 4628471
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream request: "/?"
2022/04/11 15:32:23 [debug] 4047#4047: *45 http upstream dummy handler
