almostintuitive commented on PR #4433:
URL: https://github.com/apache/iggy/pull/4433#issuecomment-6044243711
Thanks for this fix, @numinnex. Before it lands, we want to report a
regression we hit while testing it.
**Summary.** With this PR applied on current master (`43fb44364` + PR head
`4b3e5684b`), a 3-node cluster loses **every acknowledged message** in a
`--durability persisted` topic when each node is SIGKILLed and restarted in
turn while writes are in flight. Master alone passes the same test. In the
logs, the first node restarted under load gets stuck: its partition is fenced
from `commit_min=0`, and repair never gets past the first `repair_chunk_max`
(128) ops. In a narrowed 1-partition repro, raising `cluster.repair_chunk_max`
to 1024 makes the failing configuration pass (we have not tried this on the
original 6-partition configuration). That points at an interaction between the
new view fence and chunked repair (analysis below; not proven).
### Setup
- Three real server processes in Docker. Each node has 2 CPUs and 4 GiB, a
Docker volume for its data dir, `seccomp=unconfined` for io_uring, 2 shards, a
1 GiB memory pool, cluster auth on, and otherwise default config.
- One stream and one topic, `topic create <s> <t> <N> none unlimited
--durability persisted`, with no other topic options.
- Six Rust-SDK producers send batches of 20 messages (~256 B payloads,
partitioned by key). A failed send is retried with the same messages until it
is acknowledged. About 20% of sends are resends of earlier acknowledged
messages, some from fresh sessions.
- Fault schedule, measured from the start of load: kill node 0 at 15 s and
start it at 30 s, kill node 1 at 45 s and start it at 60 s, kill node 2 at 75 s
and start it at 90 s. Kills are `docker kill -s KILL`, and each node restarts
from its volume. Load lasts 90 s.
- Once all nodes are up, a verifier reads each partition from offset 0 up to
the `current_offset` reported by GetTopic. Empty polls are retried for up to
120 s. Every acknowledged message must be present.
### Results: original configuration (6 partitions, ~2,000 msg/s)
| Server build | Result |
|---|---|
| master `43fb44364` | PASS. 0 of 154,180 acknowledged messages lost
(173,636 in the log, including retry duplicates) |
| **master + this PR (`4b3e5684b`)** | **FAIL ×2. 91,680 and 91,320
acknowledged; 0 messages in the log** |
| `f6dfbdbb3` (parent of #4387) | PASS. 0 of 153,720 lost |
| `f6dfbdbb3` + #4429 (backport) | PASS ×2. 0 of 150,900 and 0 of 152,780
lost |
| `f6dfbdbb3` + #4429 + this PR (backport with small adaptations, e.g.
`FatalCommit.operation` is not an `Option` there, so `Operation::Reserved`) |
FAIL. All 95,280 lost, same symptom |
In the failing runs every send was acknowledged in the end. Send latency
peaked at ~31 s, and a few dozen transient errors were retried. After the run,
the GetTopic answer from each of the three nodes is `Topic size 0 B`, `Topic
message count 0`, and every partition polls empty. The same schedule with no
load during the kills did not lose data.
### Narrowed repro (1 partition, same kill schedule unless noted)
| Build | Rate | Result |
|---|---|---|
| master | 500 msg/s | PASS. 0 of 40,480 lost |
| master + PR | 500 msg/s | FAIL. 23,120 of 23,120 lost |
| master | 150 msg/s | PASS ×2. 0 of 13,460 and 0 of 13,560 lost |
| master + PR | 150 msg/s | FAIL ×2. 7,860 of 7,860 and 6,840 of 6,840 lost |
| master + PR, `IGGY_CLUSTER_REPAIR_CHUNK_MAX=1024` | 150 msg/s | PASS ×2. 0
of 13,460 and 0 of 12,700 lost |
| master + PR, `IGGY_CLUSTER_REPAIR_CHUNK_MAX=1024` | 500 msg/s | PASS. 0 of
37,320 lost (but one node showed the stall below; see analysis) |
| master + PR, **one** kill/restart only (node 0) | 150 msg/s | PASS. 0 of
9,800 lost, but node 0 never caught up (below) |
One FAIL run at 150 msg/s queried GetTopic on every node between steps.
These queries shifted the later steps by up to ~45 s. After node 1 was killed,
the message count stopped at 7,495 on every node that answered; in the same
window of the master control run, the count went from 9,546 to 15,070. The
count stayed at 7,495 after node 1 restarted. Within 5 s of killing node 2, the
two remaining nodes (both restarted earlier) answered **0**. Max send latency
in that run was 125.7 s (master: 15.1 s).
### What the logs show
The narrowed single-kill run (PR, 1 partition, 150 msg/s) shows the stall on
its own. After restarting, node 0 fences its whole history and asks a peer for
ops 1..247. The peer serves through op 128. Node 0 then asks for 1..247 again,
about once per second, for the next ~100 s, until the logs were collected:
```
node-0 18:16:48.668 INFO partitions::iggy_partition: holding partition
entries journaled before this view until its log proves them namespace_raw=0
view=1 commit_min=0 through=246 anchored=true
node-0 18:16:48.669 INFO shard: partition behind the group frontier;
requesting repair namespace_raw=0 from_op=1 commit_to_op=247 fetch_to_op=247
peer=1
node-1 18:16:48.671 INFO shard: served partition repair range
namespace_raw=0 target=0 from_op=1 to_op=247 served_through=128
node-0 18:16:49.780 INFO shard: partition repair stalled; re-requesting
remaining window namespace_raw=0 from_op=1 to_op=247 peer=1
node-1 18:16:49.784 INFO shard: served partition repair range
namespace_raw=0 target=0 from_op=1 to_op=247 served_through=128
... (97 re-requests in total, last one at 18:18:26, still from_op=1
to_op=247)
```
The original 6-partition failing runs show the same pattern on every
partition of the first restarted node, with ~90 re-requests from `from_op=1`.
After that come `partition repair stalled past its retry budget; re-arming from
another replica ... from_op=1`, `partition journal repair completed or was
superseded ... commit_min=0 consensus_view=2` once node 1 is killed, and `no
header at this replica's commit point; the DVC reports it blank and cannot nack
it, so the view change stalls unless a peer supplies it op=466 commit=466`. The
stuck node also fails to apply the live stream: `error="Cannot append message"
failed to apply replicated partition operation`, followed by `dropping
out-of-order prepare` for every later op.
For comparison, on master a restarted node asks for `from_op=65` and walks
the window one chunk at a time. For example, its `commit_min` goes 731 → 1062 →
1140, and repair completes within a few seconds. Master never logs a repair
request from `from_op=1` in these runs.
A correction to something we first suspected: the segment recovery warning
below appears on **every** build after each SIGKILL, master included, so it is
not specific to this PR:
```
WARN partitions::segment_recovery: truncating a segment file to its
recovered bounds; discarding torn tail bytes
path="local_data/streams/0/topics/0/partitions/3/00000000000000000000.index"
current_size=480 target_size=0
```
On `f6dfbdbb3`-based builds it comes with `segment log holds bytes but no
whole batch decodes anywhere in it (torn write); recovering the segment as
empty and fencing its files aside ... messages_size=4014015`. So in this setup,
on every build, a restarted replica rebuilds its partition history from peers
through repair. This may be expected, but it explains why a repair that never
finishes ends up losing data.
### Analysis (our reading of the code; please correct us)
1. On the first `StartView` adoption after boot, `recovered_unproven`
(`persistence.head() > 0`) sets `fence_below`. `fence_unproven_view_window`
then fences `(commit_min, anchor.op - 1]`, which is `(0, 246]` above.
2. While `view_fenced()` holds, `commit_journal` returns early after
`prove_view_window()` and `collect_committable_from_journal` returns nothing.
`commit_min` therefore cannot move until every op up to `through` is present
and chains to the anchor.
3. Partition repair moves to the next chunk only when `commit_min` moves
(`partition_repair_next_chunk` needs `commit_min > before`). The stall retry
re-requests from `commit_min + 1`, and the server serves at most
`repair_chunk_max` ops per request.
4. So when the fenced window is wider than `repair_chunk_max`, the requester
receives ops 1..128. The window still has a hole at the top, so `commit_min`
stays at 0, and the same chunk is requested again. Nothing ever fetches
129..`through`. The runs match this in both directions. With chunk 128, the
first restarted node stalled this way on every partition in all 5 failing runs
on master + PR, and in the single-kill run (windows of 156 to 644 ops). With
chunk 1024, restarts whose window was smaller completed in a single chunk:
252/543/810 and 246/561/761 ops in the two 150 msg/s runs, and 551 in the 500
msg/s run. The only one that stalled was a node whose window was 1,492 ops: 15
re-requests of 1..1493, `served_through=1024`. That run still passed,
presumably because the other restarted node had caught up.
5. Our guess at how a stall turns into total loss (not traced in detail):
the stuck replica holds no history and cannot append live prepares. While
fenced, `fenced_serve_ceiling` caps its repair serving at its own `commit_min`
(0). The later restarts in the 128-chunk runs looked wrong in other ways too.
In one run, the second restarted node fenced `(0, 413]` and sent no partition
repair request at all. In another, it fenced `(0, 1365]` and, as primary-elect,
repaired only ops 1420..1425 before logging `partition journal repair
complete`. Once the last never-restarted replica is killed, the remaining
replicas appear to form a view without the history.
### What we have not established
- The exact path from "stuck replica" to "all three nodes report 0 messages"
(step 5 above).
- Why the restarted replica fences from `commit_min=0` with the PR, while on
master it resumes at op 65.
- Why recovered segment bounds are 0 after every SIGKILL on all builds. This
may be by design, and we have not looked into it.
- Whether the idle case passes only because no restart needed more than one
chunk. We did not check window sizes in that run.
- We have not written a simulator or integration test. Something like
"restart a backup under live traffic while the cluster is more than
`repair_chunk_max` ops ahead of its recovered WAL, then assert it reaches
`commit_max`" looks like the shape of it.
<details>
<summary>Cluster setup used (plain Docker)</summary>
```bash
NET=repro; SUB=172.50.0; docker network create --subnet $SUB.0/24 $NET
for i in 0 1 2; do
roster=()
for n in 0 1 2; do
roster+=(-e IGGY_CLUSTER_NODES_${n}_NAME=node-$n -e
IGGY_CLUSTER_NODES_${n}_IP=$SUB.1$n
-e IGGY_CLUSTER_NODES_${n}_REPLICA_ID=$n -e
IGGY_CLUSTER_NODES_${n}_PORTS_TCP=8090
-e IGGY_CLUSTER_NODES_${n}_PORTS_QUIC=8080 -e
IGGY_CLUSTER_NODES_${n}_PORTS_HTTP=3000
-e IGGY_CLUSTER_NODES_${n}_PORTS_WEBSOCKET=8092 -e
IGGY_CLUSTER_NODES_${n}_PORTS_TCP_REPLICA=9090)
done
docker run -d --name node-$i --hostname node-$i --network $NET --ip
$SUB.1$i \
--cpus 2 --memory 4g --security-opt seccomp=unconfined -v
node-$i:/app/local_data \
-e IGGY_ROOT_USERNAME=iggy -e IGGY_ROOT_PASSWORD=iggy \
-e IGGY_TCP_ADDRESS=$SUB.1$i:8090 -e IGGY_HTTP_ADDRESS=$SUB.1$i:3000 \
-e IGGY_QUIC_ENABLED=false -e IGGY_WEBSOCKET_ENABLED=false \
-e IGGY_SHARDING_CPU_ALLOCATION=2 -e IGGY_SHARDING_PIN_CORES=false -e
IGGY_MEMORY_POOL_SIZE=1GiB \
-e IGGY_CLUSTER_ENABLED=true -e IGGY_CLUSTER_NAME=repro \
-e IGGY_CLUSTER_AUTH_ENABLED=true -e
IGGY_CLUSTER_AUTH_SHARED_SECRET=<48-char secret> \
"${roster[@]}" <server image built from 4b3e5684b> --replica-id $i
done
iggy --transport tcp --tcp-server-address $SUB.10:8090 -u iggy -p iggy
stream create s
iggy --transport tcp --tcp-server-address $SUB.10:8090 -u iggy -p iggy topic
create s t 1 none unlimited --durability persisted
# Start a producer that retries every failed batch until acked (~150 msg/s,
batches of 20), then:
sleep 15; docker kill -s KILL node-0; sleep 15; docker start node-0
docker logs -f node-0 2>&1 | grep -E 'holding partition
entries|re-requesting remaining window'
# For the data loss, continue: kill node-1 at 45 s, start it at 60 s; kill
node-2 at 75 s, start it at 90 s.
```
</details>
We can share the full node logs and verifier output from any of these runs,
rerun with a different `RUST_LOG`, or test a candidate fix in the same setup.
Just let us know what would help.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
