Re: [PATCH net-next v3 7/7] tls: rx: do not use the standard strparser

[Tariq Toukan <ttoukan.linux@gmail.com>]

On 23/07/2022 2:50, Jakub Kicinski wrote:
> TLS is a relatively poor fit for strparser. We pause the input
> every time a message is received, wait for a read which will
> decrypt the message, start the parser, repeat. strparser is
> built to delineate the messages, wrap them in individual skbs
> and let them float off into the stack or a different socket.
> TLS wants the data pages and nothing else. There's no need
> for TLS to keep cloning (and occasionally skb_unclone()'ing)
> the TCP rx queue.
> 
> This patch uses a pre-allocated skb and attaches the skbs
> from the TCP rx queue to it as frags. TLS is careful never
> to modify the input skb without CoW'ing / detaching it first.
> 
> Since we call TCP rx queue cleanup directly we also get back
> the benefit of skb deferred free.
> 
> Overall this results in a 6% gain in my benchmarks.
> 
> Signed-off-by: Jakub Kicinski <kuba@kernel.org>

Hi Jakub,

A few fixes were introduced for this patch, but it seems to still cause 
issues.

I'm running simple client/server test with wrk and nginx and TLS RX 
device offload on.
It fails with TlsDecryptError on the client side for the large file 
(256000b), while succeeding for the small one (10000b). See repro 
details below.

I narrowed the issue down to this offending patch, by applying a few 
reverts (had to solve trivial conflicts):

Revert "tls: rx: do not use the standard strparser"
Revert "tls: rx: fix the false positive warning"
Revert "tls: rx: device: bound the frag walk"
Revert "tls: rx: device: don't try to copy too much on detach"
Revert "tls: rx: react to strparser initialization errors"
Revert "tls: strp: make sure the TCP skbs do not have overlapping data"

The error is caught by the if below, inside gcmaes_decrypt.

  819         /* Compare generated tag with passed in tag. */ 

  820         if (crypto_memneq(auth_tag_msg, auth_tag, auth_tag_len)) { 

  821                 memzero_explicit(auth_tag, sizeof(auth_tag)); 

  822                 return -EBADMSG; 

  823         }

but I couldn't yet identify the root cause.

Any idea what could it be?

Reproduction:

$ ethtool --features eth2 tls-hw-rx-offload on

$ wrk_openssl_3_0_0 -b2.2.2.2 -t10 -c1000 -d5 --timeout 5s 
https://2.2.2.3:20443/10000b.img
Running 5s test @ https://2.2.2.3:20443/10000b.img
   10 threads and 1000 connections
Ready 8/10
Ready 2/10
Ready 9/10
Ready 3/10
Ready 4/10
Ready 6/10
Ready 0/10
Ready 1/10
Ready 7/10
Ready 5/10
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
   Thread Stats   Avg      Stdev     Max   +/- Stdev
     Latency   112.97ms   19.05ms 160.31ms   80.71%
     Req/Sec     0.88k   122.34     1.07k    61.86%
   37495 requests in 5.06s, 366.24MB read
Requests/sec:   7415.86
Transfer/sec:     72.44MB

$ cat /proc/net/tls_stat
TlsCurrTxSw                             0
TlsCurrRxSw                             0
TlsCurrTxDevice                         0
TlsCurrRxDevice                         0
TlsTxSw                                 0
TlsRxSw                                 0
TlsTxDevice                             1000
TlsRxDevice                             1000
TlsDecryptError                         0
TlsRxDeviceResync                       1000
TlsDecryptRetry                         0
TlsRxNoPadViolation                     0

$ wrk_openssl_3_0_0 -b2.2.2.2 -t10 -c1000 -d5 --timeout 5s 
https://2.2.2.3:20443/256000b.img
Running 5s test @ https://2.2.2.3:20443/256000b.img
   10 threads and 1000 connections
Ready 6/10
Ready 2/10
Ready 7/10
Ready 9/10
Ready 1/10
Ready 4/10
Ready 8/10
Ready 3/10
Ready 5/10
Ready 0/10
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
Ready all
   Thread Stats   Avg      Stdev     Max   +/- Stdev
     Latency     3.94s   106.78ms   4.10s    50.00%
     Req/Sec     0.67      0.82     2.00     83.33%
   38 requests in 7.71s, 154.14MB read
   Socket errors: connect 0, read 1810, write 0, timeout 0
Requests/sec:      4.93
Transfer/sec:     19.98MB

$ cat /proc/net/tls_stat
TlsCurrTxSw                             0
TlsCurrRxSw                             0
TlsCurrTxDevice                         0
TlsCurrRxDevice                         0
TlsTxSw                                 0
TlsRxSw                                 0
TlsTxDevice                             3810
TlsRxDevice                             3810
TlsDecryptError                         3634
TlsRxDeviceResync                       3060
TlsDecryptRetry                         0
TlsRxNoPadViolation                     0

More monitors:

$ bpftrace -e 'kretprobe:generic_gcmaes_decrypt { @retval[retval] = 
count(); }'
Attaching 1 probe...
^C

@retval[4294967222]: 2067
@retval[0]: 26143


$ bpftrace -e 'kprobe:generic_gcmaes_decrypt { @[kstack] = count(); }'
Attaching 1 probe...
^C

@[
     generic_gcmaes_decrypt+1
     tls_decrypt_sg+1258
     tls_rx_one_record+72
     tls_sw_recvmsg+870
     inet_recvmsg+71
     sock_recvmsg+68
     ____sys_recvmsg+111
     ___sys_recvmsg+126
     __sys_recvmsg+78
     do_syscall_64+61
     entry_SYSCALL_64_after_hwframe+70
]: 27623