openresty / openresty/openresty

ngx_lua error: epoll_ctl(1, 53) failed (17: File exists) when OpenResty+quiche

Open
#772 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
C
Stars
14k
Forks
1.6k
PR merge metrics
No merged PRs in 30d

Description

I test quic+http3 through OpenResty-1.15.8+quiche, the epoll_ctl error will appear,when the WAF module developed based on lua-nginx-module is open,disappear after closing. WAF is called in the access phase.
epoll_ctl error msg: epoll_ctl(1, 53) failed (17: File exists)

  • env
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
            ...

	}
}
  • example of waf code
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

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by reproducing the OpenResty 1.15.8.1 plus quiche setup with the WAF enabled through access_by_lua_file my_waf.lua, then inspect the debug log around the epoll add event and the Lua access handler. Done means isolating the interaction that causes the duplicate epoll_ctl registration and documenting a verified resolution or precise upstream diagnosis.

Written by the indexing model from the issue text.

Assessment

Tech stack
c
Domain
networking
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.