Regression in "nvme connect-all -t tcp" in 2.12

[bluca]

Hi,

Since version 2.12 appeared in various distributions, we have started to see occasional failures in the systemd integration test that uses nvme-cli:

[   10.378713] TEST-84-STORAGETM.sh[316]: + nvme connect-all -t tcp -a 127.0.0.1 -s 16858 --hostid=95fe8041-3f53-415b-bc40-1bbd8932e7e8
[   10.397892] nvme_tcp: queue 0: failed to receive icresp, error -4
[   10.397326] TEST-84-STORAGETM.sh[340]: failed to add controller, error failed to write to nvme-fabrics device

This test runs dozens if not hundreds of times every day and it was stable until 2.12. Are you aware of any potential issues/changes?

You can find the full test script here:

https://github.com/systemd/systemd/blob/main/test/units/TEST-84-STORAGETM.sh

[igaw]

Hi,

[ 10.397892] nvme_tcp: queue 0: failed to receive icresp, error -4

Is the test suite runnning against the same kernel or has it been updated also? Or in other words is this a new warning? I didn't spot any obvious commit from a quick glance in libnvme and nvme-cli which could cause a regression.

I wonder if this is related to https://lore.kernel.org/linux-nvme/08c29e4b-2f71-4b6d-8046-27e407214d8c@suse.com/

[bluca]

The kernel in this case is 6.13.8

Full (very verbose, including image build) log: https://productionresultssa11.blob.core.windows.net/actions-results/68ef4d36-6a89-4db7-ab5e-4b8d78357c5c/workflow-job-run-ab2a2163-2e0e-540b-4bd7-05f43b11d9c3/logs/job/job-logs.txt?rsct=text%2Fplain&se=2025-03-31T14%3A23%3A06Z&sig=T%2FcJ8HJd67kV%2Blub5TAL5EVe08Taa%2FHxeoqWbjSeyog%3D&ske=2025-04-01T00%3A00%3A35Z&skoid=ca7593d4-ee42-46cd-af88-8b886a2f84eb&sks=b&skt=2025-03-31T12%3A00%3A35Z&sktid=398a6654-997b-47e9-b12b-9515b896b4de&skv=2025-01-05&sp=r&spr=https&sr=b&st=2025-03-31T14%3A13%3A01Z&sv=2025-01-05

This is not just a warning, but a full error that is failing the test case, and it was first observed with 2.12

[igaw]

It's an error and not a warning.

If you provide the very verbose option -vv the tool will print out which command string passes it passes down to the kernel (/dev/nvme-fabrics). The diff between the two versions would help a lot.

Anyway, could you post the logs, I can't access them AuthenticationFailed

[hreinecke]

My bet would be on commit 578539e09690 ("nvme-tcp: fix connect failure on receiving partial ICResp PDU")...

[bluca]

I'll add the -vv flag to the test, but it will be a while before it reproduces (it's not 100%), I'll report when I see it

Full log attached:

log_nvme.gz

[igaw]

The test is using hostid as id type, hostnqn is the preferred type. Not sure if this is the problem. I've opened an issue for it, so we don't forget about it.

systemd/systemd#36908

[igaw]

578539e09690

That one went in v6.13.7

[igaw]

@bluca would it be possible to test without the commit @hreinecke identified? It really looks like a kernel bug.

[bluca]

If someone can provide me with a kernel package I can try to reproduce it locally and with/without, but I'm not really equipped for building kernels myself

[igaw]

Understood, these things are always a bit complicated. Maybe I can reproduce it locally.

Independent what causes the error, nvme-cli is not retrying on the initial connect attempt. It only tries once.

The error returned is Interrupted system call. We could either retry in userland if we get this error or possible retry in the kernel. I'll ask on the mailing list what should happen in this case.

[bluca]

Got a hit with -vv enabled:

[   11.098125] TEST-84-STORAGETM.sh[459]: + nvme connect-all -vv -t tcp -a 127.0.0.1 -s 16858 --hostnqn=nqn.2014-08.org.nvmexpress:uuid:3d3937bb-da6a-464d-9c80-01c2eb31a6c0
[   11.108825] TEST-84-STORAGETM.sh[483]: kernel supports: instance cntlid transport traddr trsvcid nqn queue_size nr_io_queues reconnect_delay ctrl_loss_tmo keep_alive_tmo hostnqn host_traddr host_iface hostid duplicate_connect disable_sqflow hdr_digest data_digest nr_write_queues nr_poll_queues tos keyring tls_key fast_io_fail_tmo discovery dhchap_secret dhchap_ctrl_secret tls concat
[   11.111388] TEST-84-STORAGETM.sh[483]: connect ctrl, 'nqn=nqn.2014-08.org.nvmexpress.discovery,transport=tcp,traddr=127.0.0.1,trsvcid=16858,hostnqn=nqn.2014-08.org.nvmexpress:uuid:3d3937bb-da6a-464d-9c80-01c2eb31a6c0,hostid=3d3937bb-da6a-464d-9c80-01c2eb31a6c0,ctrl_loss_tmo=600'
[   11.121204] nvme nvme0: failed to connect socket: -512
[   11.128693] TEST-84-STORAGETM.sh[483]: connect ctrl, response 'instance=0,cntlid=1'
[   11.130555] TEST-84-STORAGETM.sh[483]: nvme0: nqn.2014-08.org.nvmexpress.discovery connected
[   11.131182] TEST-84-STORAGETM.sh[483]: lookup subsystem /sys/class/nvme-subsystem/nvme-subsys0/nvme0
[   11.132851] TEST-84-STORAGETM.sh[483]: nvme0: get header (try 0/10)
[   11.133538] TEST-84-STORAGETM.sh[483]: nvme0: get 2 records (genctr 3)
[   11.134286] TEST-84-STORAGETM.sh[483]: nvme0: get header again[   11.140199] nvme_tcp: queue 0: failed to receive icresp, error -4

[   11.138621] TEST-84-STORAGETM.sh[483]: lookup ctrl (transport: tcp, traddr: 127.0.0.1, trsvcid 16858)
[   11.139315] TEST-84-STORAGETM.sh[483]: connect ctrl, 'nqn=quux.storagetm.test,transport=tcp,traddr=127.0.0.1,trsvcid=16858,hostnqn=nqn.2014-08.org.nvmexpress:uuid:3d3937bb-da6a-464d-9c80-01c2eb31a6c0,hostid=3d3937bb-da6a-464d-9c80-01c2eb31a6c0,ctrl_loss_tmo=600,disable_sqflow'
[   11.144247] TEST-84-STORAGETM.sh[483]: Failed to write to /dev/nvme-fabrics: Interrupted system call
[   11.145208] TEST-84-STORAGETM.sh[483]: nvme0: nqn.2014-08.org.nvmexpress.discovery disconnected[   11.150498] n
vmet_tcp: failed to allocate queue, error -107
[   11.153280] TEST-84-STORAGETM.sh[483]: opcode       : 06
[   11.153621] TEST-84-STORAGETM.sh[483]: flags        : 00
[   11.153899] TEST-84-STORAGETM.sh[483]: rsvd1        : 0000
[   11.156314] TEST-84-STORAGETM.sh[483]: nsid         : 00000000
[   11.159884] TEST-84-STORAGETM.sh[483]: cdw2         : 00000000
[   11.161371] TEST-84-STORAGETM.sh[483]: cdw3         : 00000000
[   11.16[228](https://github.com/systemd/systemd/actions/runs/14284399200/job/40037745890?pr=37022#step:13:229)1] TEST-84-STORAGETM.sh[483]: data_len     : 00001000
[   11.162759] TEST-84-STORAGETM.sh[483]: metadata_len : 00000000
[   11.163432] TEST-84-STORAGETM.sh[483]: addr         : 555d6ea07000
[   11.165286] TEST-84-STORAGETM.sh[483]: metadata     : 0
[   11.165896] TEST-84-STORAGETM.sh[483]: cdw10        : 00000001
[   11.166637] TEST-84-STORAGETM.sh[483]: cdw11        : 00000000
[   11.169521] TEST-84-STORAGETM.sh[483]: cdw12        : 00000000
[   11.170207] TEST-84-STORAGETM.sh[483]: cdw13        : 00000000
[   11.170816] TEST-84-STORAGETM.sh[483]: cdw14        : 00000000
[   11.171397] TEST-84-STORAGETM.sh[483]: cdw15        : 00000000
[   11.172153] TEST-84-STORAGETM.sh[483]: timeout_ms   : 00000000
[   11.172796] TEST-84-STORAGETM.sh[483]: result       : 00000000
[   11.173434] TEST-84-STORAGETM.sh[483]: err          : 0
[   11.174336] TEST-84-STORAGETM.sh[483]: latency      : 1255 us

https://github.com/systemd/systemd/actions/runs/14284399200/job/40037745890?pr=37022

This was on Fedora Rawhide which currently has a kernel build from upstream main (6.15~rc0)

[igaw]

[ 11.111388] TEST-84-STORAGETM.sh[483]: connect ctrl, 'nqn=nqn.2014-08.org.nvmexpress.discovery,transport=tcp,traddr=127.0.0.1,trsvcid=16858,hostnqn=nqn.2014-08.org.nvmexpress:uuid:3d3937bb-da6a-464d-9c80-01c2eb31a6c0,hostid=3d3937bb-da6a-464d-9c80-01c2eb31a6c0,ctrl_loss_tmo=600'

This looks okay, nothing fancy going on. That basically rules out nvme-cli/libnvme as source for the regression. Let me ping the mailing list once more.

I see that libnvme sees EINTR. So the simplest way to address this would to try again to connect.