SSL 0.128 Unknown Packet packet received

[alistair23]

When trying to run nvme connect to connect to a NVMe target the kernel is reporting nvme_tcp: queue 0: failed to receive icresp, error -104. Digging into the log a bit more I see this from tlshd and gnutls

tlshd[348]: gnutls(10): RB: Requested 5 bytes
tlshd[348]: gnutls(5): REC[0x43e710]: SSL 0.128 Unknown Packet packet received. Epoch 0, length: 128
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/record.c[check_recv_type]:623
tlshd[348]: audit: Received record packet of unknown type 0
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/record.c[recv_headers]:1202
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/record.c[_gnutls_recv_in_buffers]:1292
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/buffers.c[_gnutls_handshake_io_recv_int]:1412
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/handshake.c[_gnutls_recv_handshake]:1594
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/handshake.c[handshake_server]:3505
tlshd[348]: gnutls(13): BUF[HSK]: Emptied buffer
tlshd[348]: tlshd_start_tls_handshake unhandled error -15, returning EACCES
tlshd[348]: gnutls(13): BUF[HSK]: Emptied buffer
tlshd[348]: gnutls(5): REC[0x43e710]: Start of epoch cleanup
tlshd[348]: gnutls(5): REC[0x43e710]: End of epoch cleanup
tlshd[348]: gnutls(5): REC[0x43e710]: Epoch #0 freed
tlshd[348]: gnutls(5): REC[0x43e710]: Epoch #1 freed
tlshd[348]: Handshake with 'localhost' (127.0.0.1) failed
kernel[240]: [  153.232161] nvme_tcp: *** kernel_recvmsg: ret: -104, 128
kernel[240]: [  153.232827] nvme_tcp: queue 0: failed to receive icresp, error -104

Noting that the REC[0x43e710]: SSL 0.128 Unknown Packet packet received. Epoch 0, length: 128 seems to indicate that something with the packets is very wrong as the version should be TLS1.3 and length 128.

The command I'm running is:

$ nvme connect  -t tcp -a 127.0.0.1 -s 4420 -n nqn.2014-08.org.nvmexpress.discovery -q hostnqn.software_connect -I 11111111-2222-3333-4444-555555555555  -C DHHC-1:01:jXPRppu5rb2wGnxPaM5xklVCEJ/FwlK0B9oaAAQgJwX/6EpY: -S DHHC-1:01:jXPRppu5rb2wGnxPaM5xklVCEJ/FwlK0B9oaAAQgJwX/6EpY:   -i 1

Which is attempting to connect to a nvmet on the same host.

nvme discover -t tcp -a 127.0.0.1 -s 4420 also doesn't work with a similar error

The full tlshd log looks like this

tlshd[348]: System config file: /etc/gnutls/config
tlshd[348]: gnutls(5): REC[0x43e710]: Allocating epoch #0
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/object.c:73   nl_object_alloc: Allocated new object 0x434ee0
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:288  __nlmsg_alloc: msg 0x43d520: Allocated new message, maxlen=40>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:531  nlmsg_put: msg 0x43d520: Added netlink header type=16, flags=>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:438  nlmsg_reserve: msg 0x43d520: Reserved 4 (4) bytes, pad=4, nlm>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/genl/genl.c:363  genlmsg_put: msg 0x43d520: Added generic netlink header>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/attr.c:482  nla_reserve: msg 0x43d520: attr <0x441454> 2: Reserved 16 (1>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/attr.c:519  nla_put: msg 0x43d520: attr <0x441454> 2: Wrote 10 bytes at >
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/nl.c:348  nl_sendmsg: sent 36 bytes
tlshd[348]: DBG<3>/usr/src/debug/libnl/3.11.0/lib/nl.c:841  recvmsgs: Attempting to read from 0x442630
tlshd[348]: DBG<3>/usr/src/debug/libnl/3.11.0/lib/nl.c:850  recvmsgs: recvmsgs(0x442630): Read 164 bytes
tlshd[348]: DBG<3>/usr/src/debug/libnl/3.11.0/lib/nl.c:854  recvmsgs: recvmsgs(0x442630): Processing valid message...
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:288  __nlmsg_alloc: msg 0x43d570: Allocated new message, maxlen=164
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/msg.c:578  nlmsg_free: Returned message reference 0x43d570, 0 remaining
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:586  nlmsg_free: msg 0x43d570: Freed
tlshd[348]: DBG<3>/usr/src/debug/libnl/3.11.0/lib/nl.c:841  recvmsgs: Attempting to read from 0x442630
tlshd[348]: DBG<3>/usr/src/debug/libnl/3.11.0/lib/nl.c:850  recvmsgs: recvmsgs(0x442630): Read 36 bytes
tlshd[348]: DBG<3>/usr/src/debug/libnl/3.11.0/lib/nl.c:854  recvmsgs: recvmsgs(0x442630): Processing valid message...
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:288  __nlmsg_alloc: msg 0x43d570: Allocated new message, maxlen=36
tlshd[348]: DBG<3>/usr/src/debug/libnl/3.11.0/lib/nl.c:900  recvmsgs: recvmsgs(0x442630): Increased expected sequence numb>
tlshd[348]: gnutls(5): REC[0x43e710]: Allocating epoch #1
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/msg.c:578  nlmsg_free: Returned message reference 0x43d570, 0 remaining
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:586  nlmsg_free: msg 0x43d570: Freed
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/msg.c:578  nlmsg_free: Returned message reference 0x43d520, 0 remaining
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:586  nlmsg_free: msg 0x43d520: Freed
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/object.c:227  nl_object_put: Returned object reference 0x434ee0, 0 remai>
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/object.c:194  nl_object_free: Freed object 0x434ee0
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:288  __nlmsg_alloc: msg 0x43d520: Allocated new message, maxlen=40>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:531  nlmsg_put: msg 0x43d520: Added netlink header type=28, flags=>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:438  nlmsg_reserve: msg 0x43d520: Reserved 4 (4) bytes, pad=4, nlm>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/genl/genl.c:363  genlmsg_put: msg 0x43d520: Added generic netlink header>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/attr.c:482  nla_reserve: msg 0x43d520: attr <0x441454> 1: Reserved 8 (4)>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/attr.c:519  nla_put: msg 0x43d520: attr <0x441454> 1: Wrote 4 bytes at o>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/attr.c:482  nla_reserve: msg 0x43d520: attr <0x44145c> 2: Reserved 8 (4)>
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/attr.c:519  nla_put: msg 0x43d520: attr <0x44145c> 2: Wrote 4 bytes at o>
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/nl.c:348  nl_sendmsg: sent 36 bytes
tlshd[348]: DBG<4>/usr/src/debug/libnl/3.11.0/lib/msg.c:578  nlmsg_free: Returned message reference 0x43d520, 0 remaining
tlshd[348]: DBG<2>/usr/src/debug/libnl/3.11.0/lib/msg.c:586  nlmsg_free: msg 0x43d520: Freed
tlshd[348]: DBG<1>/usr/src/debug/libnl/3.11.0/lib/cache_mngt.c:308  nl_cache_mngt_unregister: Unregistered cache operation>
kernel: nvme_tcp: queue 0: failed to receive icresp, error -104
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/buffers.c[get_last_packet]:1138
tlshd[348]: gnutls(10): READ: Got 5 bytes from 0x6
tlshd[348]: gnutls(10): READ: read 5 bytes from 0x6
tlshd[348]: gnutls(10): RB: Have 0 bytes into buffer. Adding 5 bytes.
tlshd[348]: gnutls(10): RB: Requested 5 bytes
tlshd[348]: gnutls(5): REC[0x43e710]: SSL 0.128 Unknown Packet packet received. Epoch 0, length: 128
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/record.c[check_recv_type]:623
tlshd[348]: audit: Received record packet of unknown type 0
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/record.c[recv_headers]:1202
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/record.c[_gnutls_recv_in_buffers]:1292
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/buffers.c[_gnutls_handshake_io_recv_int]:1412
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/handshake.c[_gnutls_recv_handshake]:1594
tlshd[348]: gnutls(3): ASSERT: /usr/src/debug/gnutls/3.8.9/lib/handshake.c[handshake_server]:3505
tlshd[348]: gnutls(13): BUF[HSK]: Emptied buffer
tlshd[348]: tlshd_start_tls_handshake unhandled error -15, returning EACCES
tlshd[348]: gnutls(13): BUF[HSK]: Emptied buffer
tlshd[348]: gnutls(5): REC[0x43e710]: Start of epoch cleanup
tlshd[348]: gnutls(5): REC[0x43e710]: End of epoch cleanup
tlshd[348]: gnutls(5): REC[0x43e710]: Epoch #0 freed
tlshd[348]: gnutls(5): REC[0x43e710]: Epoch #1 freed
tlshd[348]: Handshake with 'localhost' (127.0.0.1) failed
kernel[240]: [  153.232827] nvme_tcp: queue 0: failed to receive icresp, error -104

The tcpdump looks like this:

10:00:32.536576 IP (tos 0x0, ttl 64, id 62562, offset 0, flags [DF], proto TCP (6), length 60)
    localhost.41198 > localhost.4420: Flags [S], cksum 0xfe30 (incorrect -> 0x6c5f), seq 2626897829, win 65495, options [mss 65495,sackOK,TS val 177947294 ecr 0,nop,wscale 5], length 0
10:00:32.541775 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 60)
    localhost.4420 > localhost.41198: Flags [S.], cksum 0xfe30 (incorrect -> 0x0d2b), seq 3361491345, ack 2626897830, win 65483, options [mss 65495,sackOK,TS val 177947302 ecr 177947294,nop,wscale 5], length 0
10:00:32.547968 IP (tos 0x0, ttl 64, id 62563, offset 0, flags [DF], proto TCP (6), length 52)
    localhost.41198 > localhost.4420: Flags [.], cksum 0xfe28 (incorrect -> 0x2dd8), seq 1, ack 1, win 2047, options [nop,nop,TS val 177947308 ecr 177947302], length 0
10:00:32.553705 IP (tos 0x0, ttl 64, id 62564, offset 0, flags [DF], proto TCP (6), length 180)
    localhost.41198 > localhost.4420: Flags [P.], cksum 0xfea8 (incorrect -> 0x2d49), seq 1:129, ack 1, win 2047, options [nop,nop,TS val 177947314 ecr 177947302], length 128
10:00:32.554672 IP (tos 0x0, ttl 64, id 32653, offset 0, flags [DF], proto TCP (6), length 52)
    localhost.4420 > localhost.41198: Flags [.], cksum 0xfe28 (incorrect -> 0x2d49), seq 1, ack 129, win 2043, options [nop,nop,TS val 177947315 ecr 177947314], length 0
10:00:32.603343 IP (tos 0x0, ttl 64, id 32654, offset 0, flags [DF], proto TCP (6), length 52)
    localhost.4420 > localhost.41198: Flags [R.], cksum 0xfe28 (incorrect -> 0x2d10), seq 1, ack 129, win 2047, options [nop,nop,TS val 177947364 ecr 177947314], length 0

I can't figure out what is going wrong, but someone it looks like the packets are being corrupted. I'm running the 6.15-rc1 kernel and tlshd 1.0.0-rc2.