[PATCH 2 of 2] SSL: SSL_sendfile() support with kernel TLS

Mon Oct 18 22:07:44 UTC 2021

> On 18 Oct 2021, at 18:26, Sergey Kandaurov <pluknet at nginx.com> wrote:
> 
>> 
>> On 27 Sep 2021, at 16:18, Maxim Dounin <mdounin at mdounin.ru> wrote:
>> 
>> # HG changeset patch
>> # User Maxim Dounin <mdounin at 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