Open ltning opened 10 months ago
We'll try to reproduce the problem
Which http client are you using? I guess the client ended the SSL session abnormally.
Sorry for being tardy here, it's been busy. Doesn't matter which client is used (curl, wget, fetch, browser). It's the call to sleep that causes the connection to drop, and it happens instantly (regardless of the length of the sleep).
Note that for the below I changed the config to prefix my sleep function with local
to avoid the warning about accessing globals.
Wrapping ngx.sleep()
in a function was an attempt at working around this issue based on random finds on the internet. It makes no difference.
For testing right now, I'm running tail *error.log | sed 's/^/ NGINX: /g' &
and then curl
returns (with error log lines from the tail
prefixed by NGINX:
, everything else is curl
output):
# curl -vko - https://localhost:443/logos/soidfsdf/tokentest.txt
* Trying 127.0.0.1:443...
* Connected to localhost (10.4.6.44) port 443
NGINX:
NGINX: ==> /var/log/nginx/ssl-3ds-acs.ci.modirum.com-443.error.log <==
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: post event 000000083B459C40
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: delete posted event 000000083B459C40
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: accept on 0.0.0.0:443, ready: 1
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: posix_memalign: 00000008407AB200:512 @16
* NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 accept: 10.4.6.44:58770 fd:29
ALPN: curl offers h2,http/1.1
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 event timer add: 29: 5000:16537264000
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 reusable connection: 1
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 kevent set event: 29: ft:-1 fl:0025
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 post event 000000083B45A050
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 delete posted event 000000083B45A050
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 http check ssl handshake
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 http recv(): 1
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 https ssl handshake: 0x16
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 tcp_nodelay
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 reusable connection: 0
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 ssl client hello: connection reusable: 0
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 code cache lookup (key='ssl_client_hello_by_lua_nhli_f3d7b9e9ddc9a91d02d18db147f0ebb8', ref=1)
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 code cache hit (key='ssl_client_hello_by_lua_nhli_f3d7b9e9ddc9a91d02d18db147f0ebb8', ref=1)
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua creating new thread
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua reusing cached lua thread 0000000842C2C168 (ref 1)
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua run thread, top:9 c:1
NGINX: 2023/11/18 13:44:49 [error] 20076#651526: *7 [lua] ssl_client_hello_by_lua(...-acs.ci.modirum.com-443.conf:38):11: ssl_clt: table, context: ssl_client_hello_by_lua*, client: 10.4.6.44, server: 0.0.0.0:443
NGINX: 2023/11/18 13:44:49 [error] 20076#651526: *7 [lua] ssl_client_hello_by_lua(...-acs.ci.modirum.com-443.conf:38):17: SNI name: localhost, context: ssl_client_hello_by_lua*, client: 10.4.6.44, server: 0.0.0.0:443
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 event timer add: 0: 5000:16537264000
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua ready to sleep for 5000 ms
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua resume returned 1
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua thread yielded
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 http lua finalize fake request: -4, a:1, c:2
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 http lua fake request count:2
* OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to localhost:443
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 add cleanup: 00000008407AB3B8
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 SSL_do_handshake: -1
* Closing connection
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 SSL_get_error: 11
NGINX: 2023/11/18 13:44:49 [info] 20076#651526: *6 peer closed connection in SSL handshake while loading SSL client hello by lua, client: 10.4.6.44, server: 0.0.0.0:443
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 close http connection: 29
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 event timer del: 29: 16537264000
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 reusable connection: 0
curl: (35) OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to localhost:443
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 run cleanup: 00000008407AB3B8
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 lua_client_hello_by_lua: client hello cb aborted
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 http lua finalize fake request: -1, a:1, c:1
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 http lua fake request count:1
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 http lua close fake request
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 http lua close fake http connection 000000083B3D8870
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua request cleanup: forcible=0
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 http lua finalize threads
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 event timer del: 0: 16537264000
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua deleting light thread 0000000842C2C168 (ref 1)
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *7 lua caching unused lua thread 0000000842C2C168 (ref 1)
NGINX: 2023/11/18 13:44:49 [debug] 20076#651526: *6 free: 00000008407AB200, unused: 48
For comparison, removing the sleep call yields:
# curl -vko - https://localhost:443/logos/soidfsdf/tokentest.txt
* Trying 127.0.0.1:443...
* Connected to localhost (10.4.6.44) port 443
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: post event 0000000885E52800
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: delete posted event 0000000885E52800
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: accept on 0.0.0.0:443, ready: 1
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: posix_memalign: 000000082C4AE600:512 @16
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 accept: 10.4.6.44:17085 fd:19
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 event timer add: 19: 5000:16537409616
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 reusable connection: 1
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 kevent set event: 19: ft:-1 fl:0025
* ALPN: curl offers h2,http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 post event 0000000885E52AD8
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 delete posted event 0000000885E52AD8
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 http check ssl handshake
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 http recv(): 1
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 https ssl handshake: 0x16
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 tcp_nodelay
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 reusable connection: 0
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 ssl client hello: connection reusable: 0
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 code cache lookup (key='ssl_client_hello_by_lua_nhli_e46d52b46923e869f5a9a589b9771547', ref=-1)
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 code cache miss (key='ssl_client_hello_by_lua_nhli_e46d52b46923e869f5a9a589b9771547', ref=-1)
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 lua creating new thread
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 lua run thread, top:9 c:1
NGINX: 2023/11/18 13:47:14 [error] 20687#110451: *11 [lua] ssl_client_hello_by_lua(...-acs.ci.modirum.com-443.conf:38):11: ssl_clt: table, context: ssl_client_hello_by_lua*, client: 10.4.6.44, server: 0.0.0.0:443
NGINX: 2023/11/18 13:47:14 [error] 20687#110451: *11 [lua] ssl_client_hello_by_lua(...-acs.ci.modirum.com-443.conf:38):17: SNI name: localhost, context: ssl_client_hello_by_lua*, client: 10.4.6.44, server: 0.0.0.0:443
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 lua resume returned 0
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 lua light thread ended normally
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 lua deleting light thread 000000088A4973A0 (ref 1)
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 lua caching unused lua thread 000000088A4973A0 (ref 1)
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 http lua finalize fake request: 0, a:1, c:1
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 http lua fake request count:1
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 http lua close fake request
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 http lua close fake http connection 0000000885DD1BC0
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 lua request cleanup: forcible=0
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *11 http lua finalize threads
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 lua_client_hello_by_lua: handler return value: 0, client hello cb exit code: 1
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 ssl get session: 0215FD58:32
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 SSL server name: "localhost"
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 SSL ALPN supported by client: h2
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 SSL ALPN supported by client: http/1.1
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 SSL ALPN selected: h2
* TLSv1.3 (IN), TLS handshake, Server hello (2):
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 SSL_do_handshake: -1
NGINX: 2023/11/18 13:47:14 [debug] 20687#110451: *10 SSL_get_error: 2
* TLSv1.2 (IN), TLS handshake, Certificate (11):
.....
Have you applied openresty/patches/nginx-1.25.1-ssl_client_hello_cb_yield.patch? Without this patch, ngx_http_lua_ssl_client_hello_handler() will not be called again when the ssl handshake is suspended by the yield function.
I don't think that's among the patches the FreeBSD port ships with, so we'd have to update the port with that, int hat case. But is this the reason for the failure? There is no sleep happening, the failure is instant. Also, our nginx is 1.24.0. We're not on the odd releases.
Yes, it is the reason for the failre. I reproduced the problem and when I tried to fix it, I checked the patch file maintained by openresty and found it.
It doesn't apply cleanly to 1.25.3 (it seems); and not on 1.24 either:
$ cat work/nginx-1.24.0/src/event/ngx_event_openssl.c.rej
@@ -1712,6 +1712,9 @@
if (sslerr == SSL_ERROR_WANT_X509_LOOKUP
# ifdef SSL_ERROR_PENDING_SESSION
|| sslerr == SSL_ERROR_PENDING_SESSION
+# endif
+# ifdef SSL_ERROR_WANT_CLIENT_HELLO_CB
+ || sslerr == SSL_ERROR_WANT_CLIENT_HELLO_CB
# endif
)
{
I can't find SSL_ERROR_WANT_X509_LOOKUP
in any relevant place, not sure what's missing.
@ltning Sorry for the late reply as I've been busy settling in lately. I found that @zhuizhuhaomeng added patchs for nginx-1.25.1, if you update your nginx version you can use it
I think the easiest way is to use nginx that comes in the openresty bundle which is fully patched
Hey, no problem, thanks for returning to me on this. I'll give that a go; any idea when it'll be merged to an even-numbered nginx version?
no idea :)
It still doesn't work; behaviour is exactly the same as before.
As a side note: I installed nginx-devel (1.25.3), which has
--add-dynamic-module=/wrkdirs/usr/ports/www/nginx-devel/work/lua-nginx-module-0.10.26rc1
but on startup I get:
NGINX: 2023/12/11 16:47:43 [alert] 39096#300544: failed to load the 'resty.core' module (https://github.com/openresty/lua-resty-core); ensure you are using an OpenResty release from https://openresty.org/en/download.html (reason: /usr/local/share/lua/5.1/resty/core/base.lua:24: ngx_http_lua_module 0.10.25 required) in /usr/local/etc/nginx/nginx.conf:143
I've checked base.lua around line 24, and added some debugging, and found that it needs to read
or ngx.config.ngx_lua_version ~= 10026
to match the current version.
I tested it and found that ssl patches can be installed successfully in this order.
patch -p1 < ~/git/openresty/patches/nginx-1.25.1-ssl_cert_cb_yield.patch patch -p1 < ~/git/openresty/patches/nginx-1.25.1-ssl_sess_cb_yield.patch patch -p1 < ~/git/openresty/patches/nginx-1.25.1-ssl_client_hello_cb_yield.patch
I found this bash script (openresty/util/mirror-tarballs) that uses this sequence to apply the ssl patches
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
Code:
Logs: