`nvme connect` with TLS enabled is unstable

Hello, I'm interested in enabling TLS in connections between nvme-cli and Linux kernel NVMe target. I use tlshd daemon for handshake upcall and keyctl to set up session, keyring and key for the connection. I often notice that after calling nvme connect the TLS connection is being broken and re-established multiple times (tlshd shows multiple Handshake successful messages that appear every few seconds). Furthermore, after connecting to target I expect a creation of a new block device (visible via lsblk), but in cases, where TLS handshake is being re-done multiple times, the device does not appear or it pops in for a second or two and then disappears.

Here is a script I use to reproduce this issue:

test.sh (click to uncollapse)

``` SUBSYSTEM_NQN="nqn.2016-06.io.nvme:cnode0" NVME_HOSTNQN=$(nvme gen-hostnqn) NVME_HOSTID=${NVME_HOSTNQN##*:} PSK_IDENTITY="NVMe0R01 ${NVME_HOSTNQN} ${SUBSYSTEM_NQN}" TLSHD_CONF="tlshd.conf" nvmet=/sys/kernel/config/nvmet nvmet_subsys="$nvmet/subsystems/$SUBSYSTEM_NQN" nvmet_host="$nvmet/hosts/$NVME_HOSTNQN" kernel_port="/sys/kernel/config/nvmet/ports/1" kernel_subsystem="$nvmet/subsystems/$SUBSYSTEM_NQN" kernel_namespace=$kernel_subsystem/namespaces/1 key="00112233445566778899aabbccddeeff" NVMF_ADDR="127.0.0.1" NVMF_PORT="4420" NVMF_TRANSPORT=tcp construct_tlshd_conf() { local keyring_name=$1 cat << EOF > $TLSHD_CONF [debug] loglevel=0 tls=0 nl=0 [authentication] keyrings= ${keyring_name} EOF } nvmet_tls_init() { mkdir "$kernel_subsystem" mkdir "$kernel_port" echo "$SUBSYSTEM_NQN" > "$kernel_subsystem/attr_model" echo 1 > "$kernel_subsystem/attr_allow_any_host" mkdir "$kernel_namespace" echo "/dev/nullb0" > "$kernel_namespace/device_path" echo 1 > "$kernel_namespace/enable" echo "$NVMF_ADDR" > "$kernel_port/addr_traddr" echo "$NVMF_TRANSPORT" > "$kernel_port/addr_trtype" echo "$NVMF_PORT" > "$kernel_port/addr_trsvcid" echo ipv4 > "$kernel_port/addr_adrfam" echo 0 > "$nvmet_subsys/attr_allow_any_host" mkdir "$nvmet_host" ln -s "$nvmet_host" "$nvmet_subsys/allowed_hosts/$NVME_HOSTNQN" echo "tls1.3" > "$kernel_port/addr_tsas" ln -s "$kernel_subsystem" "$kernel_port/subsystems/" } waitforserial() { local i=0 local nvme_device_counter=1 nvme_devices=0 sleep 2 while ((i++ <= 60)); do nvme_devices=$(lsblk -l -o NAME,SERIAL | grep -c "$1") || nvme_devices=0 ((nvme_devices == nvme_device_counter)) && return 0 if ((nvme_devices > nvme_device_counter)); then echo "$nvme_device_counter device(s) expected, found $nvme_devices" >&2 fi echo "Waiting for devices" sleep 1 done return 1 } waitforserial_disconnect() { local i=0 while lsblk -o NAME,SERIAL | grep -q -w $1; do [ $i -lt 60 ] || break i=$((i + 1)) echo "Waiting for disconnect devices" sleep 1 done if lsblk -l -o NAME,SERIAL | grep -q -w $1; then return 1 fi return 0 } modprobe nvmet modprobe nvmet-tcp modprobe nvme modprobe nvme-fabrics modprobe nvme-tcp modprobe null_blk nr_devices=1 # setup session, keyring, add key session_id=$(keyctl show | awk '{print $1}' | tail -1) keyring_name="test_${session_id}" keyring_id=$(keyctl newring $keyring_name $session_id) keyctl setperm $keyring_id 0x3f3f0b00 key_name=test_key_${session_id} key_id=$(keyctl add psk "$PSK_IDENTITY" "$key" "$keyring_id") # setup tlshd daemon for handshake upcall construct_tlshd_conf $keyring_name tlshd -s -c "$TLSHD_CONF" & tlshdpid=$! # setup target nvmet_tls_init # start initiator nvme connect --nqn=$SUBSYSTEM_NQN --traddr=$NVMF_ADDR --trsvcid=$NVMF_PORT \ --transport=$NVMF_TRANSPORT --hostnqn=$NVME_HOSTNQN --hostid=$NVME_HOSTID \ -o normal --verbose --tls --tls_key=$key_id --keyring=$keyring_id -i 1 waitforserial "nvme0n1" nvme disconnect --nqn=$SUBSYSTEM_NQN & waitforserial_disconnect "nvme0n1" kill $tlshdpid ```

What the script does:

loads nvme/nvmet modules and a nullblock for nvmet
sets up keyctl session, keyring and key for TLS
constructs tlshd config file and launches the daemon
sets up nvmet
calls nvme connect
uses lsblk to check if a new block device is ready (here I print a log every second)
calls nvme disconnect
uses lsblk again to check if the device has been removed (I print a log as well here).

Here are the logs from the script:

script logs (click to uncollapse)

``` [vagrant@fedora38 tls]$ keyctl session Joined session keyring: 627451046 [vagrant@fedora38 tls]$ sudo ./test.sh tlshd[2321]: Built from ktls-utils 0.10 on Oct 7 2023 00:00:00 tlshd[2330]: Handshake with localhost (127.0.0.1) was successful tlshd[2331]: Handshake with localhost (127.0.0.1) was successful tlshd[2343]: Handshake with localhost (127.0.0.1) was successful tlshd[2342]: Handshake with localhost (127.0.0.1) was successful nvme0: nqn.2016-06.io.nvme:cnode0 connected connecting to device: nvme0 Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices tlshd[2509]: Handshake with localhost (127.0.0.1) was successful tlshd[2508]: Handshake with localhost (127.0.0.1) was successful tlshd[2511]: Handshake with localhost (127.0.0.1) was successful tlshd[2510]: Handshake with localhost (127.0.0.1) was successful Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices tlshd[2678]: Handshake with localhost (127.0.0.1) was successful tlshd[2677]: Handshake with localhost (127.0.0.1) was successful tlshd[2679]: Handshake with localhost (127.0.0.1) was successful tlshd[2680]: Handshake with localhost (127.0.0.1) was successful Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices tlshd[2821]: Handshake with localhost (127.0.0.1) was successful tlshd[2820]: Handshake with localhost (127.0.0.1) was successful tlshd[2822]: Handshake with localhost (127.0.0.1) was successful tlshd[2823]: Handshake with localhost (127.0.0.1) was successful Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices Waiting for devices NQN:nqn.2016-06.io.nvme:cnode0 disconnected 1 controller(s) ```

(Here I spotted these:

[   38.934816] nvme_fabrics: key id 03d25538 not found
[   38.934920] nvme_fabrics: key id 373fb1c2 not found

but the handshake completes nonetheless)

I also collected relevant entries from dmesg:

dmesg (click to uncollapse)

``` [ 38.782349] Key type psk registered [ 38.869665] null_blk: disk nullb0 created [ 38.869719] null_blk: module loaded [ 38.908813] nvmet: adding nsid 1 to subsystem nqn.2016-06.io.nvme:cnode0 [ 38.925904] nvmet_tcp: enabling port 1 (127.0.0.1:4420) [ 38.934816] nvme_fabrics: key id 03d25538 not found [ 38.934920] nvme_fabrics: key id 373fb1c2 not found [ 38.999518] nvmet: creating nvm controller 1 for subsystem nqn.2016-06.io.nvme:cnode0 for NQN nqn.2014-08.org.nvmexpress:uuid:9ea78b17-4d5a-448c-92a0-6ab8ae75556b. [ 39.003348] nvme nvme0: creating 1 I/O queues. [ 39.010552] nvme nvme0: mapped 1/0/0 default/read/poll queues. [ 39.011832] nvme nvme0: new ctrl: NQN "nqn.2016-06.io.nvme:cnode0", addr 127.0.0.1:4420 [ 46.552958] nvme nvme0: I/O tag 0 (1000) type 4 opcode 0x18 (Admin Cmd) QID 0 timeout [ 46.553080] nvme nvme0: starting error recovery [ 46.553886] nvme nvme0: failed nvme_keep_alive_end_io error=10 [ 46.554080] nvme nvme0: reading non-mdts-limits failed: -4 [ 46.560624] nvme nvme0: Reconnecting in 10 seconds... [ 57.058600] nvmet: creating nvm controller 1 for subsystem nqn.2016-06.io.nvme:cnode0 for NQN nqn.2014-08.org.nvmexpress:uuid:9ea78b17-4d5a-448c-92a0-6ab8ae75556b. [ 57.060619] nvme nvme0: creating 1 I/O queues. [ 57.070224] nvme nvme0: mapped 1/0/0 default/read/poll queues. [ 57.070710] nvme nvme0: Successfully reconnected (1 attempt) [ 64.664890] nvme nvme0: I/O tag 0 (2000) type 4 opcode 0x18 (Admin Cmd) QID 0 timeout [ 64.665045] nvme nvme0: starting error recovery [ 64.665755] nvme nvme0: failed nvme_keep_alive_end_io error=10 [ 64.665867] nvme nvme0: reading non-mdts-limits failed: -4 [ 64.672543] nvme nvme0: Reconnecting in 10 seconds... [ 74.976571] nvmet: creating nvm controller 1 for subsystem nqn.2016-06.io.nvme:cnode0 for NQN nqn.2014-08.org.nvmexpress:uuid:9ea78b17-4d5a-448c-92a0-6ab8ae75556b. [ 74.978458] nvme nvme0: creating 1 I/O queues. [ 74.988188] nvme nvme0: mapped 1/0/0 default/read/poll queues. [ 74.988605] nvme nvme0: Successfully reconnected (1 attempt) [ 82.584803] nvme nvme0: I/O tag 0 (3000) type 4 opcode 0x18 (Admin Cmd) QID 0 timeout [ 82.584913] nvme nvme0: starting error recovery [ 82.585559] nvme nvme0: failed nvme_keep_alive_end_io error=10 [ 82.585655] nvme nvme0: reading non-mdts-limits failed: -4 [ 82.592539] nvme nvme0: Reconnecting in 10 seconds... [ 92.898232] nvmet: creating nvm controller 1 for subsystem nqn.2016-06.io.nvme:cnode0 for NQN nqn.2014-08.org.nvmexpress:uuid:9ea78b17-4d5a-448c-92a0-6ab8ae75556b. [ 92.900112] nvme nvme0: creating 1 I/O queues. [ 92.908335] nvme nvme0: mapped 1/0/0 default/read/poll queues. [ 92.910425] nvme nvme0: Successfully reconnected (1 attempt) [ 100.504725] nvme nvme0: I/O tag 0 (4000) type 4 opcode 0x18 (Admin Cmd) QID 0 timeout [ 100.505515] nvme nvme0: starting error recovery [ 100.507736] nvme nvme0: failed nvme_keep_alive_end_io error=10 [ 100.507897] nvme nvme0: reading non-mdts-limits failed: -4 [ 100.514401] nvme nvme0: Reconnecting in 10 seconds... [ 103.128976] nvme nvme0: Removing ctrl: NQN "nqn.2016-06.io.nvme:cnode0" [ 103.130890] nvme nvme0: Property Set error: 880, offset 0x14 ```

My nvme-cli version:

[vagrant@fedora38 tls]$ nvme --version
nvme version 2.7.1 (git 2.7.1-10-g6cbe764+)
libnvme version 1.7 (git 1.7+)

my kernel:

[vagrant@fedora38 tls]$ uname -a
Linux fedora38.localdomain 6.8.0-0.rc1.20240123gt7ed2632e.112.vanilla.fc38.x86_64 #1 SMP PREEMPT_DYNAMIC Tue Jan 23 04:55:49 UTC 2024 x86_64 GNU/Linux

keyctl:

[vagrant@fedora38 tls]$ keyctl --version
keyctl from keyutils-1.6.1 (Built 2023-01-19)

tlshd:

[vagrant@fedora38 tls]$ tlshd --version
tlshd, built from ktls-utils 0.10 on Oct  7 2023 00:00:00

Is there a way to fix or work around this?

linux-nvme / nvme-cli

`nvme connect` with TLS enabled is unstable #2353