[PATCH 2 of 2] SSL: SSL_sendfile() support with kernel TLS
Sergey Kandaurov
pluknet at nginx.com
Mon Oct 18 15:26:47 UTC 2021
> 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".
I am not sure about mentioning ktls_ocf.ko in the commit message.
The module is only present in FreeBSD 13.0, it was removed post 13.0,
and the functionality is now always present in kernels with KERN_TLS:
https://cgit.freebsd.org/src/commit/?id=21e3c1fbe246
Further, it is one of many options to enable KTLS.
It could be better to refer to man ktls(4), instead:
: On FreeBSD, kernel TLS is available starting with FreeBSD 13.0, and
: can be enabled with "sysctl kern.ipc.tls.enable=1", see man ktls(4).
(but I don't insist)
>
> 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.
It is Ubuntu 20.04 (5.4.0) and 21.04 (5.11.0), with epoll and select
event methods. As per tcpdump traces, it looks like the buffer cannot
be pushed to the network, although it is reported as if it was sent.
The simplest I could grab (see below) with ssl_buffer_size 4k and sndbuf 8k
(note that unlike SSL_write(), buffers aren't limited with ssl_buffer_size).
It doesn't stuck starting with sndbuf 16k, so it might have something
with how KTLS send buffers correspond with TCP send buffers.
(In contrast, the FreeBSD sendfile is strictly constrained by the available
send buffer space and hence shouldn't have this problem.)
So it doesn't look like a major issue.
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL to write: 514
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL_write: 514
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL to sendfile: @0 1048576
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL_sendfile: 16384
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL to sendfile: @16384 1032192
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL_sendfile: -1
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL_get_error: 3
2021/10/18 14:16:44 [debug] 492598#0: *2 http write filter 000055E11C3C42C8
2021/10/18 14:16:44 [debug] 492598#0: *2 http copy filter: -2 "/file?"
2021/10/18 14:16:44 [debug] 492598#0: *2 http writer output filter: -2, "/file?"
2021/10/18 14:16:44 [debug] 492598#0: *2 event timer: 3, old: 350488404, new: 350488516
2021/10/18 14:16:44 [debug] 492598#0: worker cycle
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:6 wr:0
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:7 wr:0
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:8 wr:0
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:3 wr:0
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:3 wr:1
2021/10/18 14:16:44 [debug] 492598#0: max_fd: 8
2021/10/18 14:16:44 [debug] 492598#0: select timer: 59888
2021/10/18 14:16:44 [debug] 492598#0: select ready 1
2021/10/18 14:16:44 [debug] 492598#0: select write 3
2021/10/18 14:16:44 [debug] 492598#0: *2 post event 000055E11C6F5E30
2021/10/18 14:16:44 [debug] 492598#0: timer delta: 48
2021/10/18 14:16:44 [debug] 492598#0: posted event 000055E11C6F5E30
2021/10/18 14:16:44 [debug] 492598#0: *2 delete posted event 000055E11C6F5E30
2021/10/18 14:16:44 [debug] 492598#0: *2 http run request: "/file?"
2021/10/18 14:16:44 [debug] 492598#0: *2 http writer handler: "/file?"
2021/10/18 14:16:44 [debug] 492598#0: *2 http output filter "/file?"
2021/10/18 14:16:44 [debug] 492598#0: *2 http copy filter: "/file?"
2021/10/18 14:16:44 [debug] 492598#0: *2 image filter
2021/10/18 14:16:44 [debug] 492598#0: *2 xslt filter body
2021/10/18 14:16:44 [debug] 492598#0: *2 http postpone filter "/file?" 0000000000000000
2021/10/18 14:16:44 [debug] 492598#0: *2 write old buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 16384, size: 1032192
2021/10/18 14:16:44 [debug] 492598#0: *2 write old buf t:0 f:0 0000000000000000, pos 000055E11BB28D59, size: 2 file: 0, size: 0
2021/10/18 14:16:44 [debug] 492598#0: *2 write old buf t:0 f:0 0000000000000000, pos 000055E11BB28D56, size: 5 file: 0, size: 0
2021/10/18 14:16:44 [debug] 492598#0: *2 http write filter: l:1 f:0 s:1032199
2021/10/18 14:16:44 [debug] 492598#0: *2 http write filter limit 0
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL to sendfile: @16384 1032192
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL_sendfile: 16384
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL to sendfile: @32768 1015808
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL_sendfile: -1
2021/10/18 14:16:44 [debug] 492598#0: *2 SSL_get_error: 3
2021/10/18 14:16:44 [debug] 492598#0: *2 http write filter 000055E11C3C42C8
2021/10/18 14:16:44 [debug] 492598#0: *2 http copy filter: -2 "/file?"
2021/10/18 14:16:44 [debug] 492598#0: *2 http writer output filter: -2, "/file?"
2021/10/18 14:16:44 [debug] 492598#0: *2 event timer: 3, old: 350488404, new: 350488564
2021/10/18 14:16:44 [debug] 492598#0: worker cycle
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:6 wr:0
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:7 wr:0
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:8 wr:0
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:3 wr:0
2021/10/18 14:16:44 [debug] 492598#0: select event: fd:3 wr:1
2021/10/18 14:16:44 [debug] 492598#0: max_fd: 8
2021/10/18 14:16:44 [debug] 492598#0: select timer: 59840
2021/10/18 14:17:44 [debug] 492598#0: select ready 0
2021/10/18 14:17:44 [debug] 492598#0: timer delta: 59901
2021/10/18 14:17:44 [debug] 492598#0: *2 event timer del: 3: 350488404
2021/10/18 14:17:44 [debug] 492598#0: *2 http run request: "/file?"
2021/10/18 14:17:44 [debug] 492598#0: *2 http writer handler: "/file?"
2021/10/18 14:17:44 [info] 492598#0: *2 client timed out
No more events, as though "fd:3 wr:1" is set as shown above.
As per the logs, there were two successful SSL_sendfile() calls,
following a short tail of the regular SSL_write().
This doesn't correspond to "openssl s_client" strace, though:
select(4, [0 3], [], NULL, NULL) = 2 (in [0 3])
read(3, "\27\3\3\2\32", 5) = 5
read(3, "\336\331\33\223n\277:2\26Z\240p\273\f.W\324\317:~\3408F}\200~cX \362\306\275"..., 538) = 538
select(4, [0 3], [], NULL, NULL) = 2 (in [0 3])
read(3, "\27\3\3@\30", 5) = 5
read(3, "\336\331\33\223n\277:3,\33\264\17q\210\252\256\n\266\v^\244\247+\20\377j5d\336\250w\177"..., 16408) = 16408
The second buffer is postponed for some reason, until timeout:
select(4, [3], [], NULL, NULL
[.. wait for 60 seconds timeout ..]
) = 1 (in [3])
read(3, "\27\3\3@\30", 5) = 5
read(3, "\336\331\33\223n\277:4\22\276\36\0\336\274I\354\227\6\244>\16{\242\3366\254x]\367\21s\260"..., 16408) = 16408
This is confirmed by tcpdump (note a gap in timestamps),
where the second SSL_sendfile()'s data is sent delayed with a FIN.
14:16:44.911122 IP 127.0.0.1.8085 > 127.0.0.1.35024: Flags [P.], seq 1155142:1155685, ack 627, win 65392, options [nop,nop,TS val 1397093502 ecr 1397093502], length 543
14:16:44.916372 IP 127.0.0.1.35024 > 127.0.0.1.8085: Flags [.], ack 1155685, win 61875, options [nop,nop,TS val 1397093507 ecr 1397093502], length 0
14:16:44.916388 IP 127.0.0.1.8085 > 127.0.0.1.35024: Flags [.], seq 1155685:1172098, ack 627, win 65392, options [nop,nop,TS val 1397093507 ecr 1397093507], length 16413
14:16:44.958874 IP 127.0.0.1.35024 > 127.0.0.1.8085: Flags [.], ack 1172098, win 61875, options [nop,nop,TS val 1397093549 ecr 1397093507], length 0
14:17:44.859485 IP 127.0.0.1.8085 > 127.0.0.1.35024: Flags [F.], seq 1172098:1188511, ack 627, win 65392, options [nop,nop,TS val 1397153450 ecr 1397093549], length 16413
14:17:44.859734 IP 127.0.0.1.35024 > 127.0.0.1.8085: Flags [.], ack 1188512, win 49239, options [nop,nop,TS val 1397153450 ecr 1397153450], length 0
14:17:44.863155 IP 127.0.0.1.35024 > 127.0.0.1.8085: Flags [P.], seq 627:658, ack 1188512, win 49239, options [nop,nop,TS val 1397153454 ecr 1397153450], length 31
14:17:44.863171 IP 127.0.0.1.8085 > 127.0.0.1.35024: Flags [R], seq 1549272302, win 0, length 0
I've added additional debugging to SSL_sendfile()
to see that sendfile() returns EBUSY (11).
Sending the same volume of data with a regular sendfile (without SSL)
doesn't exhibit such a problem: a write event is always reported.
2021/10/18 14:47:42 [debug] 495187#0: *1 write old buf t:1 f:0 00007F6AA5FEC010, pos 00007F6AA6103F61, size: 648 file: 0, size: 0
2021/10/18 14:47:42 [debug] 495187#0: *1 write old buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 1048576
2021/10/18 14:47:42 [debug] 495187#0: *1 write old buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2021/10/18 14:47:42 [debug] 495187#0: *1 http write filter: l:1 f:0 s:1049224
2021/10/18 14:47:42 [debug] 495187#0: *1 http write filter limit 0
2021/10/18 14:47:42 [debug] 495187#0: *1 writev: 648 of 648
2021/10/18 14:47:42 [debug] 495187#0: *1 sendfile: @0 1048576
2021/10/18 14:47:42 [debug] 495187#0: *1 sendfile: 32767 of 1048576 @0
2021/10/18 14:47:42 [debug] 495187#0: *1 sendfile: @32767 1015809
2021/10/18 14:47:42 [debug] 495187#0: *1 sendfile() is not ready (11: Resource temporarily unavailable)
...
2021/10/18 14:47:42 [debug] 495187#0: *1 sendfile: @32767 1015809
2021/10/18 14:47:42 [debug] 495187#0: *1 sendfile: 32767 of 1015809 @32767
2021/10/18 14:47:42 [debug] 495187#0: *1 sendfile: @65534 983042
2021/10/18 14:47:42 [debug] 495187#0: *1 sendfile() is not ready (11: Resource temporarily unavailable)
...
...
2021/10/18 14:47:43 [debug] 495187#0: *1 sendfile: @1048544 32
2021/10/18 14:47:43 [debug] 495187#0: *1 sendfile: 32 of 32 @1048544
The patches look good.
--
Sergey Kandaurov
More information about the nginx-devel
mailing list