kvcache-ai / kvcache-ai/Mooncake

[Bug]: RDMA reconnect storm after mlx5 local length errors

Open
#3,299 3 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
C++
Stars
6.6k
Forks
1.2k
Avg merge
3d 5h
Merged PRs (30d)
312

Description

### Bug Report

### Environment

- Mooncake version: likely `v0.3.12.post1` based on the source line numbers in the logs; exact Git SHA and image digest are still being confirmed.
- Deployment: multi-node production-like workload.
- Caller: an SGLang-like process using Mooncake for RDMA transfers.
- RDMA devices: `mlx5_bond_0` and `mlx5_bond_1`.
- OS/kernel, NIC firmware and RDMA stack versions: being collected.

### Description

We observed an RDMA failure on a Mooncake Client node. Multiple mlx5 QPs reported `local length error`, and Mooncake reported `local access violation work queue error`.

Mooncake then repeatedly received RDMA ready ACKs, detected different peer QPNs, retired the existing endpoint and established a new connection. However, the rebuilt connection did not restore the data path: newly created QPs failed again within milliseconds, causing a reconnect loop.

At approximately the same time, the caller reported a 4096-byte RDMA WRITE failing with `remote invalid request error`.

Kernel logs from the Mooncake Client node:

```text
[Wed Jul 29 14:40:27 2026] mlx5_bond_0/1: QP 51291 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114233 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114235 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114237 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114239 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114241 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114243 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114245 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114247 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114249 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_0/1: QP 51293 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_0/1: QP 51295 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_0/1: QP 51297 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114251 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_0/1: QP 51299 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114253 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:27 2026] mlx5_bond_1/1: QP 114255 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_0/1: QP 51301 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_0/1: QP 51303 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_1/1: QP 114257 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_0/1: QP 51305 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_0/1: QP 51307 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_1/1: QP 114259 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_0/1: QP 51309 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_0/1: QP 51311 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_1/1: QP 114261 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_0/1: QP 51313 error: local length error (0x8e 0x0 0x0)
[Wed Jul 29 14:40:28 2026] mlx5_bond_0/1: QP 51315 error: local length error (0x8e 0x0 0x0)
```

Mooncake Client logs during the reconnect loop:

```text
W0729 14:42:36.623718 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_0
I0729 14:42:36.623723 rdma_endpoint.cpp:671] Received RDMA ready ACK.
W0729 14:42:36.629417 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.629431 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.636394 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
I0729 14:42:36.641793 rdma_endpoint.cpp:671] Received RDMA ready ACK.
W0729 14:42:36.647222 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.647228 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.653996 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
I0729 14:42:36.659399 rdma_endpoint.cpp:671] Received RDMA ready ACK.
W0729 14:42:36.664911 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.664916 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.670414 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
I0729 14:42:36.675731 rdma_endpoint.cpp:671] Received RDMA ready ACK.
W0729 14:42:36.679523 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.679529 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.685294 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
I0729 14:42:36.690742 rdma_endpoint.cpp:671] Received RDMA ready ACK.
W0729 14:42:36.694644 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.694648 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.700307 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
I0729 14:42:36.705766 rdma_endpoint.cpp:671] Received RDMA ready ACK.
W0729 14:42:36.709558 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.709563 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.715221 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
I0729 14:42:36.720575 rdma_endpoint.cpp:671] Received RDMA ready ACK.
W0729 14:42:36.724505 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 14:42:36.724510 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
```

The same pattern recurred later across multiple peer endpoints:

```text
W0729 15:13:49.587558 233 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_0
W0729 15:13:49.591352 237 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_2
W0729 15:13:49.591361 237 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_2
W0729 15:13:49.596343 236 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
W0729 15:13:49.600895 237 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 15:13:49.600903 237 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_0
W0729 15:13:49.605129 236 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
W0729 15:13:49.609689 237 rdma_endpoint.cpp:692] Re-establish connection: EndPoint: local @mlx5_bond_1, peer @mlx5_bond_2
W0729 15:13:49.609701 237 rdma_endpoint.cpp:864] Retiring endpoint instead of resetting it (triggered by: re-establishing connection (passive)): EndPoint: local @mlx5_bond_1, peer @mlx5_bond_2
W0729 15:13:49.613919 236 worker_pool.cpp:938] Worker: Received context async event local access violation work queue error for context mlx5_bond_1
E0729 15:13:49.661269 237 transfer_metadata_plugin.cpp:821] Socket read failed while waiting client to close: Connection reset by peer [104]
I0729 15:13:49.661477 237 rdma_endpoint.cpp:671] Received RDMA ready ACK.
I0729 15:13:49.661505 237 rdma_endpoint.cpp:671] Received RDMA ready ACK.
E0729 15:13:49.661986 237 transfer_metadata_plugin.cpp:821] Socket read failed while waiting client to close: Connection reset by peer [104]
W0729 15:13:49.662007 237 common.h:375] Socket read incompleted: expected 8 bytes, actual 0 bytes
E0729 15:13:49.662011 237 common.h:452] readString: failed to read length, got: 0
E0729 15:13:49.662032 237 transfer_metadata_plugin.cpp:767] SocketHandShakePlugin: failed to receive handshake message, malformed json format: * Line 1, Column 1
Syntax error: value, object or array expected.
, json string length: 0, json string content:
I0729 15:14:09.654368 237 rdma_endpoint.cpp:671] Received RDMA ready ACK.
```

Caller-side(Sglang) failure with sensitive values redacted:

```text
E0729 14:42:44.772425 worker_pool.cpp:606] Worker: Process failed for slice (opcode: 1, source_addr: , length: 4096, dest_addr: , local_nic: mlx5_bond_0, peer_nic: @mlx5_bond_1, dest_rkey: , retry_cnt: 0, max_retry_cnt: 9): remote invalid request error
```

### Reproduction

We currently do not have a deterministic reproducer.

### Suspected causes

These are unconfirmed hypotheses based on the logs and source-code analysis:

- **Possible initial length/range fault:** the deployed version may advertise a buffer range that is larger than the actual registered MR, or submit a request that crosses an MR boundary. Either case can make an address look valid in Mooncake metadata while the RNIC cannot execute the complete WQE against one MR.
- **Possible recovery race between a reconnected QP and already prepared slices:** QP reconnection does not automatically rebuild or invalidate slices that were prepared before the reconnect. The handshake can make a new QP ready without proving that those slices still contain valid remote address, length and rkey information.

The relevant code order in `v0.3.12.post1` is:

1. [`WorkerPool::submitPostSend()`](https://github.com/kvcache-ai/Mooncake/blob/v0.3.12.post1/mooncake-transfer-engine/src/transport/rdma_transport/worker_pool.cpp#L115-L251) reads `SegmentDesc`, checks the slice's `dest_addr` and `length`, selects a buffer/device, and copies the selected rkey and peer NIC path into the slice.
2. The prepared slice is then enqueued. It can wait in the queue while the endpoint is disconnected or being re-established.
3. Later, the transfer worker checks the endpoint and may establish a new QP before sending the queued slice ([connection check and setup](https://github.com/kvcache-ai/Mooncake/blob/v0.3.12.post1/mooncake-transfer-engine/src/transport/rdma_transport/worker_pool.cpp#L390-L497)). A passive handshake from the peer can also replace the endpoint during this interval.
4. At the final send stage, [`RdmaEndPoint::submitPostSend()`](https://github.com/kvcache-ai/Mooncake/blob/v0.3.12.post1/mooncake-transfer-engine/src/transport/rdma_transport/rdma_endpoint.cpp#L915-L990) does not fetch or validate `SegmentDesc` again. It directly builds the WQE from the values already stored in the slice: `slice->rdma.dest_addr`, `slice->length`, and `slice->rdma.dest_rkey`.

In short:

```text
prepare slice with address/length/rkey
-> enqueue slice
-> QP fails and a new QP becomes ready
-> post the already prepared slice on the new QP
```

Endpoint locking prevents the handshake code and `ibv_post_send()` from modifying the same endpoint concurrently. However, a QP change does not cause an already prepared slice to re-read its MR metadata. The handshake carries QP/path information but no MR generation or metadata revision ([`HandShakeDesc`](https://github.com/kvcache-ai/Mooncake/blob/v0.3.12.post1/mooncake-transfer-engine/include/transfer_metadata.h#L158-L174)).

Therefore, a slice prepared before the reconnect may still be posted on the new QP using the previously selected address, length and rkey. If that MR description is stale or structurally invalid, the new QP may fail again immediately and trigger another reconnect.

Could the maintainers confirm whether this is a known issue and whether the current `main` branch already contains the relevant fix?

### Before submitting...

- [x] Ensure you searched for relevant issues and read the [documentation]

Contributor guide

Open the contributing guide

Research direction

Start by reading mooncake-transfer-engine/src/transport/rdma_transport/worker_pool.cpp around WorkerPool::submitPostSend(), then trace the reconnect and endpoint-retirement paths in rdma_endpoint.cpp. Use the provided mlx5 and Mooncake logs to follow prepared slices across QP failure and reconnection; done means the reconnect storm and invalid 4096-byte request are explained and a deterministic regression test or reproducer demonstrates the fix.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp
Domain
networking
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Active
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.