ngx.sleep() does not work in ssl_client_hello_by_lua*

Inizia riproducendo il problema con la configurazione mostrata ssl_client_hello_by_lua_block e ngx.sleep(5) su una build di debug di nginx. Leggi il punto di ingresso del client-hello SSL e la sequenza registrata di lua sleep e finalizzazione dell’handshake. Il lavoro è completato quando la connessione TCP rimane aperta durante lo sleep e l’handshake SSL continua invece di essere interrotto.

When trying to call ngx.sleep() in a ssl_client_hello_by_lua_block, the TCP connection is instantly dropped (FIN). Nginx built with --with-debug and --with-debuglog. Logs at end of report.

OS: FreeBSD 13.2-RELEASE

# nginx -V
nginx version: nginx/1.24.0
built with OpenSSL 1.1.1o-freebsd  3 May 2022 (running with OpenSSL 1.1.1t-freebsd  7 Feb 2023)
TLS SNI support enabled
configure arguments: --prefix=/usr/local/etc/nginx --with-cc-opt='-I /usr/local/include' --conf-path=/usr/local/etc/nginx/nginx.conf --sbin-path=/usr/local/sbin/nginx --pid-path=/var/run/nginx.pid --error-log-path=/var/log/nginx/error.log --user=www --group=www --with-compat --with-pcre --with-debug --modules-path=/usr/local/libexec/nginx --with-file-aio --with-google_perftools_module --http-client-body-temp-path=/var/tmp/nginx/client_body_temp --http-fastcgi-temp-path=/var/tmp/nginx/fastcgi_temp --http-proxy-temp-path=/var/tmp/nginx/proxy_temp --http-scgi-temp-path=/var/tmp/nginx/scgi_temp --http-uwsgi-temp-path=/var/tmp/nginx/uwsgi_temp --http-log-path=/var/log/nginx/access.log --with-http_v2_module --with-http_addition_module --with-http_auth_request_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_realip_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_xslt_module --without-mail_pop3_module --with-mail_ssl_module --with-stream_realip_module --with-stream_ssl_module --with-stream_ssl_preread_module --with-threads --with-http_image_filter_module=dynamic --with-http_xslt_module=dynamic --with-mail=dynamic --with-stream=dynamic --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/ngx_devel_kit-0.3.2 --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/ngx_brotli-9aec15e --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/ngx_http_auth_pam_module-1.5.3 --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/ngx-fancyindex-0.5.2 --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/lua-nginx-module-0.10.25 --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/ModSecurity-nginx-1.0.3 --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/set-misc-nginx-module-3937e7b --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/nginx-module-vts-bf64dbf --add-dynamic-module=/wrkdirs/usr/ports/www/nginx/work/passenger-6.0.17/src/nginx_module --with-ld-opt='-L /usr/local/lib -lpcre'

# pkg info | grep -E 'nginx|lua'
lua-resty-core-0.1.27          New FFI-based Lua API for OpenResty NGINX Lua modules
lua-resty-lrucache-0.13        Lua-land LRU cache based on the LuaJIT FFI
luajit-openresty-2.1.20230410_1 Just-In-Time Compiler for Lua (OpenResty branch)
nginx-1.24.0_11,3              Robust and small WWW server

Code:

ssl_client_hello_by_lua_block {
    function mysleep(n)
        ngx.sleep(n)
    end

    -- local semaphore = require "ngx.semaphore"
    -- local sema = semaphore.new()
    -- sema:wait(5)

    local ssl_clt = require "ngx.ssl.clienthello"
    ngx.log(ngx.ERR, "ssl_clt: ", type(ssl_clt))

    local host, err = ssl_clt.get_client_hello_server_name()
    if not host then
        ngx.log(ngx.ERR, "failed to get the SNI name: ", err)
    else
        ngx.log(ngx.ERR, "SNI name: ", host)
    end

    mysleep(5)
}

Logs:

2023/08/25 12:21:33 [debug] 18678#977527: kevent set event: 11: ft:-1 fl:0005
2023/08/25 12:21:35 [debug] 18678#977527: accept on 0.0.0.0:443, ready: 1
2023/08/25 12:21:35 [debug] 18678#977527: posix_memalign: 00000008448DA600:512 @16
2023/08/25 12:21:35 [debug] 18678#977527: *2 accept: 10.4.6.51:16175 fd:16
2023/08/25 12:21:35 [debug] 18678#977527: *2 event timer add: 16: 5000:9188270397
2023/08/25 12:21:35 [debug] 18678#977527: *2 reusable connection: 1
2023/08/25 12:21:35 [debug] 18678#977527: *2 kevent set event: 16: ft:-1 fl:0025
2023/08/25 12:21:35 [debug] 18678#977527: *2 http check ssl handshake
2023/08/25 12:21:35 [debug] 18678#977527: *2 http recv(): 1
2023/08/25 12:21:35 [debug] 18678#977527: *2 https ssl handshake: 0x16
2023/08/25 12:21:35 [debug] 18678#977527: *2 tcp_nodelay
2023/08/25 12:21:35 [debug] 18678#977527: *2 reusable connection: 0
2023/08/25 12:21:35 [debug] 18678#977527: *2 ssl client hello: connection reusable: 0
2023/08/25 12:21:35 [debug] 18678#977527: *3 code cache lookup (key='ssl_client_hello_by_lua_nhli_c9375228ccf6e2b45269933b001ca1f7', ref=-1)
2023/08/25 12:21:35 [debug] 18678#977527: *3 code cache miss (key='ssl_client_hello_by_lua_nhli_c9375228ccf6e2b45269933b001ca1f7', ref=-1)
2023/08/25 12:21:35 [debug] 18678#977527: *3 lua creating new thread
2023/08/25 12:21:35 [debug] 18678#977527: *3 lua run thread, top:9 c:1
2023/08/25 12:21:35 [warn] 18678#977527: *3 [lua] _G write guard:12: __newindex(): writing a global Lua variable ('mysleep') which may lead to race conditions between concurrent requests, so prefer the use of 'local' variables
stack traceback:
        ssl_client_hello_by_lua(...-acs.ci.modirum.com-443.conf:21):2: in main chunk, context: ssl_client_hello_by_lua*, client: 10.4.6.51, server: 0.0.0.0:443
2023/08/25 12:21:35 [error] 18678#977527: *3 [lua] ssl_client_hello_by_lua(...-acs.ci.modirum.com-443.conf:21):11: ssl_clt: table, context: ssl_client_hello_by_lua*, client: 10.4.6.51, server: 0.0.0.0:443
2023/08/25 12:21:35 [error] 18678#977527: *3 [lua] ssl_client_hello_by_lua(...-acs.ci.modirum.com-443.conf:21):17: SNI name: oracle-acs.ci.modirum.com, context: ssl_client_hello_by_lua*, client: 10.4.6.51, server: 0.0.0.0:443
2023/08/25 12:21:35 [debug] 18678#977527: *3 event timer add: 0: 5000:9188270397
2023/08/25 12:21:35 [debug] 18678#977527: *3 lua ready to sleep for 5000 ms
2023/08/25 12:21:35 [debug] 18678#977527: *3 lua resume returned 1
2023/08/25 12:21:35 [debug] 18678#977527: *3 lua thread yielded
2023/08/25 12:21:35 [debug] 18678#977527: *3 http lua finalize fake request: -4, a:1, c:2
2023/08/25 12:21:35 [debug] 18678#977527: *3 http lua fake request count:2
2023/08/25 12:21:35 [debug] 18678#977527: *2 add cleanup: 00000008448DA7B8
2023/08/25 12:21:35 [debug] 18678#977527: *2 SSL_do_handshake: -1
2023/08/25 12:21:35 [debug] 18678#977527: *2 SSL_get_error: 11
2023/08/25 12:21:35 [info] 18678#977527: *2 peer closed connection in SSL handshake while loading SSL client hello by lua, client: 10.4.6.51, server: 0.0.0.0:443
2023/08/25 12:21:35 [debug] 18678#977527: *2 close http connection: 16
2023/08/25 12:21:35 [debug] 18678#977527: *2 event timer del: 16: 9188270397
2023/08/25 12:21:35 [debug] 18678#977527: *2 reusable connection: 0
2023/08/25 12:21:35 [debug] 18678#977527: *2 run cleanup: 00000008448DA7B8
2023/08/25 12:21:35 [debug] 18678#977527: *2 lua_client_hello_by_lua: client hello cb aborted
2023/08/25 12:21:35 [debug] 18678#977527: *3 http lua finalize fake request: -1, a:1, c:1
2023/08/25 12:21:35 [debug] 18678#977527: *3 http lua fake request count:1
2023/08/25 12:21:35 [debug] 18678#977527: *3 http lua close fake request
2023/08/25 12:21:35 [debug] 18678#977527: *3 http lua close fake http connection 000000083EC90A20
2023/08/25 12:21:35 [debug] 18678#977527: *3 lua request cleanup: forcible=0
2023/08/25 12:21:35 [debug] 18678#977527: *3 http lua finalize threads
2023/08/25 12:21:35 [debug] 18678#977527: *3 event timer del: 0: 9188270397
2023/08/25 12:21:35 [debug] 18678#977527: *3 lua deleting light thread 0000000845A47360 (ref 1)
2023/08/25 12:21:35 [debug] 18678#977527: *3 lua caching unused lua thread 0000000845A47360 (ref 1)
2023/08/25 12:21:35 [debug] 18678#977527: *2 free: 00000008448DA600, unused: 48