OpenResty-1.15.8测试HTTP3时，使用ngx_lua后有epoll_ctl(1, 53) failed (17: File exists)的错误

lizj3624 · Sep 23, 2021

我这边正在测试验证QUIC+HTTP3，目前是用的OpenResty-1.15.8+quiche，当启用基于lua-nginx-module开发的WAF模块时，就会出现epoll_ctl(1, 53) failed (17: File exists)的错误，各位有遇到类似情况吗？

OpenResty的编译环境
nginx version: openresty/1.15.8.1 (quiche-09c0e37)
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-36) (GCC)
built with OpenSSL 1.1.1 (compatible; BoringSSL) (running with BoringSSL)
TLS SNI support enabled
configure arguments: --prefix=/export/servers/myngx/nginx --with-debug --with-cc-opt='-DNGX_LUA_USE_ASSERT -DNGX_LUA_ABORT_AT_PANIC -O2 -ggdb -O2 -D JD_NGX_SSL_HANDSHAKE_TIME -D JD_NGX_HTTP_UPSTREAM_RANDOM' --add-module=../ngx_devel_kit-0.3.1rc1 --add-module=../echo-nginx-module-0.61 --add-module=../xss-nginx-module-0.06 --add-module=../ngx_coolkit-0.2 --add-module=../set-misc-nginx-module-0.32 --add-module=../form-input-nginx-module-0.12 --add-module=../encrypted-session-nginx-module-0.08 --add-module=../srcache-nginx-module-0.31 --add-module=../ngx_lua-0.10.15 --add-module=../ngx_lua_upstream-0.07 --add-module=../headers-more-nginx-module-0.33 --add-module=../array-var-nginx-module-0.05 --add-module=../memc-nginx-module-0.19 --add-module=../redis2-nginx-module-0.15 --add-module=../redis-nginx-module-0.3.7 --add-module=../rds-json-nginx-module-0.15 --add-module=../rds-csv-nginx-module-0.09 --add-module=../ngx_stream_lua-0.0.7 --with-ld-opt=-Wl,-rpath,/export/servers/myngx/luajit/lib --build=quiche-09c0e37 --with-pcre=/root/rpmbuild/BUILD/myngx-2.3-52.d375389/thirdparty/pcre-8.39 --with-pcre-jit --with-zlib=/root/rpmbuild/BUILD/myngx-2.3-52.d375389/thirdparty/zlib-1.2.8 --with-threads --with-http_auth_request_module --with-http_ssl_module --with-http_gzip_static_module --with-http_stub_status_module --with-http_v2_module --with-http_realip_module --with-http_addition_module --with-http_slice_module --add-module=/root/rpmbuild/BUILD/myngx-2.3-52.d375389/thirdparty/lua-ssl-nginx-module --add-module=/root/rpmbuild/BUILD/myngx-2.3-52.d375389/thirdparty/ngx_http_dyups_module --add-module=/root/rpmbuild/BUILD/myngx-2.3-52.d375389/thirdparty/ngx_http_sticky_module --with-stream --with-stream_ssl_module --with-http_v3_module --with-openssl=/root/myhome/quiche-cloudflare/deps/boringssl --with-quiche=/root/myhome/quiche-cloudflare --with-stream --with-stream_ssl_preread_module
ngx的conf配置
http {
...
lua_max_running_timers 512;
lua_max_pending_timers 1024;

lua_package_path "$prefix/app/lib/?.lua;$prefix/app/etc/?.lua;$prefix/app/src/?.lua;$prefix/sbin/openresty/lualib/?.lua;;";
lua_package_cpath "$prefix/app/lib/?.so;$prefix/sbin/openresty/lualib/?.so;;";

lua_check_client_abort on;
lua_socket_log_errors off;
lua_http10_buffering off;
...

server {
listen :443 quic reuseport;
isten :443 ssl http2;
...
access_by_lua_file my_waf.lua
...

}
}
WAF模块的相关代码逻辑
my_waf.lua

_M.waf_request = function ()
...ngx.req.get_body_file()..
local http_conn = http.new()
...http_conn.connect()...
...http_conn.request()...
...

end

debug相关log
2021/09/07 17:45:19 [debug] 20071#20071: epoll timer: 11
2021/09/07 17:45:23 [debug] 20071#20071: epoll: fd:53 ev:0001 d:00007FC51420C911
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 idle handler
2021/09/07 17:45:23 [debug] 20071#20071: *22622 reusable connection: 0
2021/09/07 17:45:23 [debug] 20071#20071: *22622 posix_memalign: 0000000001939E60:4096 @16
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 read handler
2021/09/07 17:45:23 [debug] 20071#20071: *22622 SSL_read: 66
2021/09/07 17:45:23 [debug] 20071#20071: *22622 SSL_read: 17
2021/09/07 17:45:23 [debug] 20071#20071: *22622 SSL_read: 15
2021/09/07 17:45:23 [debug] 20071#20071: *22622 SSL_read: -1
2021/09/07 17:45:23 [debug] 20071#20071: *22622 SSL_get_error: 2
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 frame type:1 f:24 l:57 sid:13
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 HEADERS frame sid:13 depends on 0 excl:1 weight:220
2021/09/07 17:45:23 [debug] 20071#20071: *22622 posix_memalign: 0000000001811D00:1024 @16
2021/09/07 17:45:23 [debug] 20071#20071: *22622 posix_memalign: 0000000001942840:4096 @16
2021/09/07 17:45:23 [debug] 20071#20071: *22622 posix_memalign: 00000000016EBE40:4096 @16
2021/09/07 17:45:23 [debug] 20071#20071: *22622 malloc: 0000000001960E60:32768
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 3
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: ":method: POST"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 67
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: ":authority: quic-my.com"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 7
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: ":scheme: https"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed name: 4
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 encoded string, len:41
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http uri: "/api"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http args: "appid=nettest&t=1511418329196"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http exten: ""
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: ":path: /api?appid=netDiag&functionId=netMonitor&t=1511418329196"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 66
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: "content-length: 6"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 65
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: "origin: https://h5.my.com"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 64
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: "useragent: Cronet"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 63
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: "content-type: application/x-www-form-urlencoded"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 62
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: "user-agent: com.my.app.mall/89743 (Linux; U; Android 9; zh_CN_#Hans; MHA-TL00; Build/HUAWEIMHA-TL00; Cronet/94.0.4590.0)"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 get indexed header: 16
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 header: "accept-encoding: gzip, deflate"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 request line: "POST /api?appid=netDiag&functionId=netMonitor&t=1511418329196 HTTP/2.0"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 generic phase: 0
2021/09/07 17:45:23 [debug] 20071#20071: *22622 rewrite phase: 1
2021/09/07 17:45:23 [debug] 20071#20071: *22622 rewrite phase: 2
2021/09/07 17:45:23 [debug] 20071#20071: *22622 test location: "/"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 using configuration "/"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http cl:6 max:0
2021/09/07 17:45:23 [debug] 20071#20071: *22622 rewrite phase: 4
2021/09/07 17:45:23 [debug] 20071#20071: *22622 rewrite phase: 5
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http script value: "xian_api.my.com"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http script set $dy_ups
2021/09/07 17:45:23 [debug] 20071#20071: *22622 post rewrite phase: 6
2021/09/07 17:45:23 [debug] 20071#20071: *22622 generic phase: 7
2021/09/07 17:45:23 [debug] 20071#20071: *22622 generic phase: 8
2021/09/07 17:45:23 [debug] 20071#20071: *22622 generic phase: 9
2021/09/07 17:45:23 [debug] 20071#20071: *22622 access phase: 10
2021/09/07 17:45:23 [debug] 20071#20071: *22622 access phase: 11
2021/09/07 17:45:23 [debug] 20071#20071: *22622 access phase: 12
2021/09/07 17:45:23 [debug] 20071#20071: *22622 access phase: 13
2021/09/07 17:45:23 [debug] 20071#20071: *22622 lua access handler, uri:"/api" c:1
2021/09/07 17:45:23 [debug] 20071#20071: *22622 looking up Lua code cache with key 'nhlf_a42347a02136ae9ebacc67b26bbc3dc7'
2021/09/07 17:45:23 [debug] 20071#20071: *22622 lua creating new thread
2021/09/07 17:45:23 [debug] 20071#20071: *22622 lua reset ctx
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http cleanup add: 00000000016EC608
2021/09/07 17:45:23 [debug] 20071#20071: *22622 epoll add event: fd:53 op:1 ev:00002001
2021/09/07 17:45:23 [alert] 20071#20071: *22622 epoll_ctl(1, 53) failed (17: File exists), client: 223.104.24.101, server: api.my.com, request: "POST /api?appid=nettest&t=1511418329196 HTTP/2.0", host: "quic-my.com"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http finalize request: -1, "/api?appid=netDiag&functionId=netMonitor&t=1511418329196" a:1, c:1
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http terminate request count:1
2021/09/07 17:45:23 [debug] 20071#20071: *22622 lua request cleanup: forcible=0
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http terminate cleanup count:1 blk:0
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http posted request: "/api?appid=netDiag&functionId=netMonitor&t=1511418329196"
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http terminate handler count:1
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http request count:1 blk:0
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 close stream 13, queued 0, processing 1, pushing 0
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http2 send RST_STREAM frame sid:13, status:2
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http close request
2021/09/07 17:45:23 [debug] 20071#20071: *22622 http log handler
2021/09/07 17:45:23 [debug] 20071#20071: *22622 free: 0000000001960E60
2021/09/07 17:45:23 [debug] 20071#20071: *22622 free: 0000000001942840, unused: 3
2021/09/07 17:45:23 [debug] 20071#20071: *22622 free: 00000000016EBE40, unused: 1905
2021/09/07 17:45:23 [debug] 20071#20071: *22622 free: 0000000001811D00, unused: 615

2021/09/07 17:45:23 [debug] 20071#20071: *22556 generic phase: 8
2021/09/07 17:45:23 [debug] 20071#20071: *22556 generic phase: 9
2021/09/07 17:45:23 [debug] 20071#20071: *22556 access phase: 10
2021/09/07 17:45:23 [debug] 20071#20071: *22556 access phase: 11
2021/09/07 17:45:23 [debug] 20071#20071: *22556 access phase: 12
2021/09/07 17:45:23 [debug] 20071#20071: *22556 access phase: 13
2021/09/07 17:45:23 [debug] 20071#20071: *22556 lua access handler, uri:"/api" c:1
2021/09/07 17:45:23 [debug] 20071#20071: *22556 looking up Lua code cache with key 'nhlf_a42347a02136ae9ebacc67b26bbc3dc7'
2021/09/07 17:45:23 [debug] 20071#20071: *22556 lua creating new thread
2021/09/07 17:45:23 [debug] 20071#20071: *22556 lua reset ctx
2021/09/07 17:45:23 [debug] 20071#20071: *22556 http cleanup add: 0000000001943118
2021/09/07 17:45:23 [debug] 20071#20071: *22556 epoll add event: fd:14 op:1 ev:00002001
2021/09/07 17:45:23 [alert] 20071#20071: *22556 epoll_ctl(1, 14) failed (17: File exists), client: 175.149.103.63, server: my.com, request: "POST /api?appid=nettest&t=1511418329196 HTTP/3", host: "quic-my.com"
2021/09/07 17:45:23 [debug] 20071#20071: *22556 http finalize request: -1, "/api?appid=netDiag&functionId=netMonitor&t=1511418329196" a:1, c:1
2021/09/07 17:45:23 [debug] 20071#20071: *22556 http terminate request count:1
2021/09/07 17:45:23 [debug] 20071#20071: *22556 lua request cleanup: forcible=0
2021/09/07 17:45:23 [debug] 20071#20071: *22556 http terminate cleanup count:1 blk:0
2021/09/07 17:45:23 [debug] 20071#20071: *22556 http3 handle connection
2021/09/07 17:45:23 [debug] 20071#20071: *22556 quic done reading
2021/09/07 17:45:23 [debug] 20071#20071: *22556 post event 00007FC512F45B70
2021/09/07 17:45:23 [debug] 20071#20071: *18257 recvmsg: fd:14 n:45
2021/09/07 17:45:23 [debug] 20071#20071: *18257 quic read handler
2021/09/07 17:45:23 [debug] 20071#20071: quiche: a52e201036dd3be9e161257847d65d7227fbe2da rx pkt Short dcid=a52e201036dd3be9e161257847d65d7227fbe2da key_phase=false len=24 pn=47
2021/09/07 17:45:23 [debug] 20071#20071: quiche: a52e201036dd3be9e161257847d65d7227fbe2da rx frm STREAM id=6 off=8 len=1 fin=false
2021/09/07 17:45:23 [debug] 20071#20071: quiche: a52e201036dd3be9e161257847d65d7227fbe2da rx frm PADDING len=2