> On 18 Oct 2021, at 18:26, Sergey Kandaurov <pluk...@nginx.com> wrote: > >> >> On 27 Sep 2021, at 16:18, Maxim Dounin <mdou...@mdounin.ru> wrote: >> >> # HG changeset patch >> # User Maxim Dounin <mdou...@mdounin.ru> >> # Date 1632717779 -10800 >> # Mon Sep 27 07:42:59 2021 +0300 >> # Node ID ff514bf17f7f2257dcf036c5c973b74672cefa9a >> # Parent 8f0fd60c33c106fba5f1ce3cafe990f15fcccc0c >> SSL: SSL_sendfile() support with kernel TLS. >> >> Requires OpenSSL 3.0 compiled with "enable-ktls" option. Further, KTLS >> needs to be enabled in kernel, and in OpenSSL, either via OpenSSL >> configuration file or with "ssl_conf_command Options KTLS;" in nginx >> configuration. >> >> On FreeBSD, kernel TLS is available starting with FreeBSD 13.0, and >> can be enabled with "sysctl kern.ipc.tls.enable=1" and "kldload ktls_ocf". > > [..] >> >> On Linux, kernel TLS is available starting with kernel 4.13 (at least 5.2 >> is recommended), and needs kernel compiled with CONFIG_TLS=y (with >> CONFIG_TLS=m, which is used at least on Ubuntu 21.04 by default, >> the tls module needs to be loaded with "modprobe tls"). >> > > On Linux I observe a problem sending data with short socket buffer space.
For the record, there are interesting code paths with TLSv1.3 early data. A request is read in 0-RTT, with read handler left unlocked to discard body: 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL_read_early_data: 1, 1 2021/10/18 21:34:47 [debug] 529189#0: *2 select del event fd:3 ev:8193 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL: TLSv1.3, cipher: "TLS_AES_256_GCM_SHA384 TLSv1.3 Kx=any Au=any Enc=AESGCM(256) Mac=AEAD" 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL reused session 2021/10/18 21:34:47 [debug] 529189#0: *2 BIO_get_ktls_send(): 1 2021/10/18 21:34:47 [debug] 529189#0: *2 reusable connection: 1 2021/10/18 21:34:47 [debug] 529189#0: *2 http wait request handler 2021/10/18 21:34:47 [debug] 529189#0: *2 malloc: 000055BB455E9380:1024 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL_read_early_data: 1, 54 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL_read_early_data: 0, 0 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL_get_error: 2 2021/10/18 21:34:47 [debug] 529189#0: *2 reusable connection: 0 2021/10/18 21:34:47 [debug] 529189#0: *2 posix_memalign: 000055BB455CEFF0:4096 @16 2021/10/18 21:34:47 [debug] 529189#0: *2 http process request line 2021/10/18 21:34:47 [debug] 529189#0: *2 http request line: "GET /file HTTP/1.1" 2021/10/18 21:34:47 [debug] 529189#0: *2 http uri: "/file" 2021/10/18 21:34:47 [debug] 529189#0: *2 http args: "" 2021/10/18 21:34:47 [debug] 529189#0: *2 http exten: "" 2021/10/18 21:34:47 [debug] 529189#0: *2 posix_memalign: 000055BB4590D9B0:4096 @16 2021/10/18 21:34:47 [debug] 529189#0: *2 http process request header line 2021/10/18 21:34:47 [debug] 529189#0: *2 http header: "Host: localhost" 2021/10/18 21:34:47 [debug] 529189#0: *2 http header: "Content-Length: 10" 2021/10/18 21:34:47 [debug] 529189#0: *2 http header done [..] Buffers to send: 2021/10/18 21:34:47 [debug] 529189#0: *2 http chunk: 1048576 2021/10/18 21:34:47 [debug] 529189#0: *2 write old buf t:1 f:0 00007F19F2641010, pos 00007F19F2741010, size: 98810 file: 0, size: 0 2021/10/18 21:34:47 [debug] 529189#0: *2 write new buf t:1 f:0 000055BB4590E440, pos 000055BB4590E440, size: 8 file: 0, size: 0 2021/10/18 21:34:47 [debug] 529189#0: *2 write new buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 1048576 2021/10/18 21:34:47 [debug] 529189#0: *2 write new buf t:0 f:0 0000000000000000, pos 000055BB43B53E39, size: 2 file: 0, size: 0 Header is eventually written after several write events. Note disabled reading due to a pending SSL_write_early_data() (will return to this later): 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL buf copy: 1048576 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL to write: 1048576 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL_write_early_data: 0, 0 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL_get_error: 3 2021/10/18 21:34:47 [debug] 529189#0: *2 SSL_write_early_data: want write [..] 2021/10/18 21:34:47 [debug] 529189#0: select ready 1 2021/10/18 21:34:47 [debug] 529189#0: select read 3 2021/10/18 21:34:47 [debug] 529189#0: *2 post event 000055BB458EB370 2021/10/18 21:34:47 [debug] 529189#0: timer delta: 8 2021/10/18 21:34:47 [debug] 529189#0: posted event 000055BB458EB370 2021/10/18 21:34:47 [debug] 529189#0: *2 delete posted event 000055BB458EB370 2021/10/18 21:34:47 [debug] 529189#0: *2 http run request: "/file?" 2021/10/18 21:34:47 [debug] 529189#0: *2 http read discarded body 2021/10/18 21:34:47 [debug] 529189#0: *2 select del event fd:3 ev:8193 [..] Eventually the buffer is written, reading is unlocked, then writing is immediately blocked on 2nd SSL_sendfile(): 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL to write: 98818 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_write_early_data: 1, 98818 2021/10/18 21:34:48 [debug] 529189#0: *2 post event 000055BB458EB370 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL to sendfile: @0 1048576 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_sendfile: 45056 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL to sendfile: @45056 1003520 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_sendfile: -1 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_get_error: 3 2021/10/18 21:34:48 [debug] 529189#0: *2 http write filter 000055BB4590E4C8 2021/10/18 21:34:48 [debug] 529189#0: *2 http copy filter: -2 "/file?" 2021/10/18 21:34:48 [debug] 529189#0: *2 http writer output filter: -2, "/file?" 2021/10/18 21:34:48 [debug] 529189#0: *2 event timer: 3, old: 376771767, new: 376771919 2021/10/18 21:34:48 [debug] 529189#0: posted event 000055BB458EB370 2021/10/18 21:34:48 [debug] 529189#0: *2 delete posted event 000055BB458EB370 2021/10/18 21:34:48 [debug] 529189#0: *2 http run request: "/file?" 2021/10/18 21:34:48 [debug] 529189#0: *2 http read discarded body 2021/10/18 21:34:48 [debug] 529189#0: shmtx lock 2021/10/18 21:34:48 [debug] 529189#0: slab alloc: 156 slot: 5 2021/10/18 21:34:48 [debug] 529189#0: slab alloc: 00007F19F275E200 2021/10/18 21:34:48 [debug] 529189#0: slab alloc: 128 slot: 4 2021/10/18 21:34:48 [debug] 529189#0: slab alloc: 00007F19F275C180 2021/10/18 21:34:48 [debug] 529189#0: *2 ssl new session: 7C15F467:32:156 2021/10/18 21:34:48 [debug] 529189#0: shmtx unlock 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_read_early_data: 2, 0 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_read: -1 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_get_error: 3 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_read: want write 2021/10/18 21:34:48 [debug] 529189#0: *2 event timer del: 3: 376715951 2021/10/18 21:34:48 [debug] 529189#0: *2 event timer add: 3: 5000:376716919 "SSL_read: want write" looks somewhat amusing to me. I've annotated certain OpenSSL parts to see what's happened: - first, it is SSL_sendfile() that blocks on writing, due to sendfile() returned EAGAIN, and signals SSL_ERROR_WANT_WRITE - then SSL_read_early_data() is called. Per the return code, it is the last part of reading 0-RTT. All the handshake messages are received to the moment, which is confirmed with the SSL_CTX_sess_set_new_cb() callback that is always called post-handshake in TLSv1.3; here it is called while in SSL_read_early_data(), which means that we've already received Client Finished and are ready to receive ordinal application data (aka 1-RTT). It looks like there's no any errors, but actually there's still a pending write from SSL_sendfile(). There's even a nested SSL_get_error() called from within SSL_read_early_data() to check why we couldn't actually write session ticket(s): https://github.com/openssl/openssl/blob/openssl-3.0.0/ssl/statem/statem_srvr.c#L988 I've noticed this after annotating SSL_get_error(). - then SSL_read() is called, now it is logged in nginx as an error signalled with SSL_ERROR_WANT_WRITE. It is tried to write session ticket(s) again, to no avail. Eventually, no longer pending write on the next write event. Looks like successfully sent session ticket(s) under the hood. 2021/10/18 21:34:48 [debug] 529189#0: worker cycle 2021/10/18 21:34:48 [debug] 529189#0: select event: fd:6 wr:0 2021/10/18 21:34:48 [debug] 529189#0: select event: fd:7 wr:0 2021/10/18 21:34:48 [debug] 529189#0: select event: fd:8 wr:0 2021/10/18 21:34:48 [debug] 529189#0: select event: fd:3 wr:1 2021/10/18 21:34:48 [debug] 529189#0: max_fd: 8 2021/10/18 21:34:48 [debug] 529189#0: select timer: 5000 2021/10/18 21:34:48 [debug] 529189#0: select ready 1 2021/10/18 21:34:48 [debug] 529189#0: select write 3 2021/10/18 21:34:48 [debug] 529189#0: *2 post event 000055BB458F7380 2021/10/18 21:34:48 [debug] 529189#0: timer delta: 332 2021/10/18 21:34:48 [debug] 529189#0: posted event 000055BB458F7380 2021/10/18 21:34:48 [debug] 529189#0: *2 delete posted event 000055BB458F7380 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL write handler 2021/10/18 21:34:48 [debug] 529189#0: *2 http run request: "/file?" 2021/10/18 21:34:48 [debug] 529189#0: *2 http read discarded body 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_read: 10 2021/10/18 21:34:48 [debug] 529189#0: *2 select del event fd:3 ev:4 2021/10/18 21:34:48 [debug] 529189#0: *2 post event 000055BB458F7380 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_read: avail:0 2021/10/18 21:34:48 [debug] 529189#0: *2 http finalize request: -4, "/file?" a:1, c:2 2021/10/18 21:34:48 [debug] 529189#0: *2 http request count:2 blk:0 2021/10/18 21:34:48 [debug] 529189#0: posted event 000055BB458F7380 2021/10/18 21:34:48 [debug] 529189#0: *2 delete posted event 000055BB458F7380 2021/10/18 21:34:48 [debug] 529189#0: *2 http run request: "/file?" 2021/10/18 21:34:48 [debug] 529189#0: *2 http writer handler: "/file?" 2021/10/18 21:34:48 [debug] 529189#0: *2 http output filter "/file?" 2021/10/18 21:34:48 [debug] 529189#0: *2 http copy filter: "/file?" 2021/10/18 21:34:48 [debug] 529189#0: *2 image filter 2021/10/18 21:34:48 [debug] 529189#0: *2 xslt filter body 2021/10/18 21:34:48 [debug] 529189#0: *2 http postpone filter "/file?" 0000000000000000 2021/10/18 21:34:48 [debug] 529189#0: *2 write old buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 45056, size: 1003520 2021/10/18 21:34:48 [debug] 529189#0: *2 write old buf t:0 f:0 0000000000000000, pos 000055BB43B53E39, size: 2 file: 0, size: 0 2021/10/18 21:34:48 [debug] 529189#0: *2 write old buf t:0 f:0 0000000000000000, pos 000055BB43B53E36, size: 5 file: 0, size: 0 2021/10/18 21:34:48 [debug] 529189#0: *2 http write filter: l:1 f:0 s:1003527 2021/10/18 21:34:48 [debug] 529189#0: *2 http write filter limit 0 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL to sendfile: @45056 1003520 2021/10/18 21:34:48 [debug] 529189#0: *2 SSL_sendfile: 61440 [..] These are internally made annotations that roughly corresponds to that part of the connection, for the record: before SSL_write_early_data WANT_WRITE #2 SSL_want_write - BIO_should_write SSL_ERROR_WANT_WRITE before SSL_write_early_data before SSL_sendfile before SSL_sendfile get_last_sys_error 11 WANT_WRITE #2 SSL_want_write - BIO_should_write SSL_ERROR_WANT_WRITE before SSL_read_early_data TLS_ST_SW_SESSION_TICKET -> SSL_get_error WANT_WRITE #2 SSL_want_write - BIO_should_write after SSL_read_early_data before SSL_read TLS_ST_SW_SESSION_TICKET -> SSL_get_error WANT_WRITE #2 SSL_want_write - BIO_should_write before ngx_ssl_handle_recv -> SSL_get_error WANT_WRITE #2 SSL_want_write - BIO_should_write SSL_ERROR_WANT_WRITE before SSL_read before SSL_sendfile -- Sergey Kandaurov _______________________________________________ nginx-devel mailing list nginx-devel@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-devel
