Nightly-test jepsen-eloqkv-rocksdbcloud-three-ng failed when FLUSHDB

[githubzilla]

What happened?

2025-08-11 19:00:53,446 - run_and_check - INFO - run command redis-cli -h compute-3 -p 6389 flushdb
2025-08-11 19:01:09,214 - run_and_check - INFO - FLUSHDB ret_code=0
stdout="Failed at acquire write intent.

"
2025-08-11 19:01:09,214 - run_and_check - INFO - FLUSHDB FAIL - LEADER node compute-3:6389 (leader) Output: Failed at acquire write intent.
2025-08-11 19:01:09,214 - run_and_check - INFO - FLUSHDB - Attempt 2/2 with 120s timeout
2025-08-11 19:01:09,214 - run_and_check - INFO - run command redis-cli -h compute-3 -p 6389 flushdb
2025-08-11 19:01:23,235 - run_and_check - INFO - FLUSHDB ret_code=0
stdout="Failed at acquire write intent.

"
2025-08-11 19:01:23,235 - run_and_check - INFO - FLUSHDB FAIL - LEADER node compute-3:6389 (leader) Output: Failed at acquire write intent.
2025-08-11 19:01:23,235 - run_and_check - INFO - FLUSHDB - Trying LEADER node compute-5:6389 (leader) with command: redis-cli -h compute-5 -p 6389 flushdb
2025-08-11 19:01:23,235 - run_and_check - INFO - FLUSHDB - Testing connection to compute-5:6389 with: redis-cli -h compute-5 -p 6389 ping
2025-08-11 19:01:23,235 - run_and_check - INFO - run command redis-cli -h compute-5 -p 6389 ping
2025-08-11 19:01:23,244 - run_and_check - INFO - FLUSHDB - Connection test successful for compute-5:6389: PONG
2025-08-11 19:01:23,244 - run_and_check - INFO - FLUSHDB - Attempt 1/2 with 90s timeout
2025-08-11 19:01:23,244 - run_and_check - INFO - run command redis-cli -h compute-5 -p 6389 flushdb
2025-08-11 19:01:38,726 - run_and_check - INFO - FLUSHDB ret_code=0
stdout="Failed at acquire write intent.

"
2025-08-11 19:01:38,726 - run_and_check - INFO - FLUSHDB FAIL - LEADER node compute-5:6389 (leader) Output: Failed at acquire write intent.
2025-08-11 19:01:38,726 - run_and_check - INFO - FLUSHDB - Attempt 2/2 with 120s timeout
2025-08-11 19:01:38,726 - run_and_check - INFO - run command redis-cli -h compute-5 -p 6389 flushdb
2025-08-11 19:01:52,739 - run_and_check - INFO - FLUSHDB ret_code=0
stdout="Failed at acquire write intent.

"
2025-08-11 19:01:52,740 - run_and_check - INFO - FLUSHDB FAIL - LEADER node compute-5:6389 (leader) Output: Failed at acquire write intent.
2025-08-11 19:01:52,740 - run_and_check - INFO - FLUSHDB - Trying LEADER node compute-6:6389 (leader) with command: redis-cli -h compute-6 -p 6389 flushdb
2025-08-11 19:01:52,740 - run_and_check - INFO - FLUSHDB - Testing connection to compute-6:6389 with: redis-cli -h compute-6 -p 6389 ping
2025-08-11 19:01:52,740 - run_and_check - INFO - run command redis-cli -h compute-6 -p 6389 ping
2025-08-11 19:01:52,749 - run_and_check - INFO - FLUSHDB - Connection test successful for compute-6:6389: PONG
2025-08-11 19:01:52,749 - run_and_check - INFO - FLUSHDB - Attempt 1/2 with 90s timeout
2025-08-11 19:01:52,749 - run_and_check - INFO - run command redis-cli -h compute-6 -p 6389 flushdb
2025-08-11 19:01:52,768 - run_and_check - INFO - FLUSHDB ret_code=0
stdout="Failed at acquire write intent.

"
2025-08-11 19:01:52,768 - run_and_check - INFO - FLUSHDB FAIL - LEADER node compute-6:6389 (leader) Output: Failed at acquire write intent.
2025-08-11 19:01:52,768 - run_and_check - INFO - FLUSHDB - Attempt 2/2 with 120s timeout
2025-08-11 19:01:52,768 - run_and_check - INFO - run command redis-cli -h compute-6 -p 6389 flushdb
2025-08-11 19:01:52,783 - run_and_check - INFO - FLUSHDB ret_code=0
stdout="Failed at acquire write intent.

Steps to Reproduce

Environment

• OS:
• Version:
• Any other relevant details:

[MrGuin]

Found one cause: eloqdata/tx_service#67.

I have enabled coredump and am trying to repoduce it.

[MrGuin]

Reproduced.

node 0 tries to start vote and become ng0 leader all the time but keeps failing:

[2025-08-13T19:07:59.017318 I 1551051]  node ng0:192.168.122.33:16394:0:0 term 159 start pre_vote
[2025-08-13T19:07:59.019912 I 1551050]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 0
[2025-08-13T19:07:59.020049 I 1551050]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.36:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 1
[2025-08-13T19:08:00.909379 I 1551051]  node ng2:192.168.122.33:16394:0:0 term 146 start pre_vote
[2025-08-13T19:08:00.911872 I 1551054]  node ng2:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.36:16394:0:0 term 146 granted 0 rejected_by_lease 0 disrupted 1
[2025-08-13T19:08:00.912024 I 1551054]  node ng2:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 146 granted 0 rejected_by_lease 0 disrupted 0
[2025-08-13T19:08:01.665920 I 1551051]  node ng0:192.168.122.33:16394:0:0 term 159 start pre_vote
[2025-08-13T19:08:01.668393 I 1551054]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.36:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 1
[2025-08-13T19:08:01.668552 I 1551054]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 0
[2025-08-13T19:08:03.621786 I 1551051]  node ng2:192.168.122.33:16394:0:0 term 146 start pre_vote
[2025-08-13T19:08:03.624083 I 1551053]  node ng2:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 146 granted 0 rejected_by_lease 0 disrupted 0
[2025-08-13T19:08:03.624393 I 1551049]  node ng2:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.36:16394:0:0 term 146 granted 0 rejected_by_lease 0 disrupted 1
[2025-08-13T19:08:04.581238 I 1551051]  node ng0:192.168.122.33:16394:0:0 term 159 start pre_vote

[2025-08-13T19:10:22.023293 I 1551050]  node ng2:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 146 granted 0 rejected_by_lease 0 disrupted 0
[2025-08-13T19:10:22.023476 I 1551050]  node ng2:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.36:16394:0:0 term 146 granted 0 rejected_by_lease 0 disrupted 1
[2025-08-13T19:10:24.622573 I 1551051]  node ng0:192.168.122.33:16394:0:0 term 159 start pre_vote
[2025-08-13T19:10:24.625460 I 1551049]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 0
[2025-08-13T19:10:24.625607 I 1551049]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.36:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 1
[2025-08-13T19:10:24.951671 I 1551051]  node ng2:192.168.122.33:16394:0:0 term 146 start pre_vote
[2025-08-13T19:10:24.954216 I 1551053]  node ng2:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 146 granted 0 rejected_by_lease 0 disrupted 0

[2025-08-13T19:10:34.809842 I 1551049]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.36:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 1
[2025-08-13T19:10:34.809984 I 1551049]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 0

After three minutes, finally succeeds by leader transfer when start following in ng0.

[2025-08-13T19:10:53.415647 I 1551051]  node ng0:192.168.122.33:16394:0:0 term 159 start pre_vote
[2025-08-13T19:10:53.417997 I 1551050]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.35:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 0
[2025-08-13T19:10:53.418406 I 1551053]  node ng0:192.168.122.33:16394:0:0 received PreVoteResponse from 192.168.122.36:16394:0:0 term 159 granted 0 rejected_by_lease 0 disrupted 1
[2025-08-13T19:10:53.948446 W 1551054]  node ng2:192.168.122.33:16394:0:0 ignore stale AppendEntries from 192.168.122.36:16394:0:0 in term 144 current_term 146
[2025-08-13T19:10:53.949865 W 1551054]  node ng2:192.168.122.33:16394:0:0 ignore stale AppendEntries from 192.168.122.36:16394:0:0 in term 144 current_term 146
[2025-08-13T19:10:53.949985 W 1551055]  node ng2:192.168.122.33:16394:0:0 ignore stale AppendEntries from 192.168.122.36:16394:0:0 in term 144 current_term 146
[2025-08-13T19:10:53.950341 I 1551050]  CC node 192.168.122.33:16390 starts following in ng#0, term: 159, leader node: 192.168.122.36:16394:0:0
[2025-08-13T19:10:53.950436 W 1551055]  node ng2:192.168.122.33:16394:0:0 ignore stale AppendEntries from 192.168.122.36:16394:0:0 in term 144 current_term 146
[2025-08-13T19:10:53.950830 I 1551055]  node ng0:192.168.122.33:16394:0:0 received RequestVote from 192.168.122.36:16394:0:0 in term 159 current_term 159 log_is_ok 1 votable_time 0
[2025-08-13T19:10:53.951313 I 1562676]  Node 0 is not leader of ng#0, requesting leader transfer from 192.168.122.36:16394:0:0

[MrGuin]

I will continue investigating this issue tomorrow.

[MrGuin]

Found one cause: eloqdata/tx_service#67.

I have enabled coredump and am trying to repoduce it.

Reproduced. Trying to figure out.

[githubzilla]

• More error logs from failed test.
  eloqkv_log_on_store4.tar.gz
  error_log.tar.gz

[MrGuin]

When one node rejoins the cluster after partition is healed, it takes dozens of seconds to on_start_following because the current leader fails to send heartbeat to it. Still don't know why, not because of brpc socket circuit breaker. Nevertheless, the cluster should work well, I've added flushdb retry in run_and_check.py. Should be enough for the test to run normally.

[MrGuin]

Test failed at flushdb acquiring write intent again after 16 iterations. This time the problem is permanent even all the nodes have recovered:

eloq@compute-1 ~$ redis-cli -h compute-6 -p 6389
compute-6:6389> flushdb
(error) Failed at acquire write intent.

Two possible causes: 1. some txm fails to decrement the catalog read cnt; 2. flushdb txn fails to release the catalog write lock on some node.
Add more debug logs and bvars to reproduce.

[MrGuin]

All the flushdb txn AcquireAllCc fails at ReaderWriterCntl::AddWriter on one node, because there is already a write_req from txn: 8800390541103, which is a failed flushdb long long ago. Then AddWriter returns WriteConflict.

[MrGuin]

Possible cause: the PostWriteAll fails to execute on the last core, thus FinishWrite is not called. To be verified.

[MrGuin]

The possible cause is that the schema_cntl write_req is not cleared when node group fails over, leaving an orphan write_req. Needs to organize schema_cntl by node group and clean it when node group fails over.

[MrGuin]

Found another bug when trying to reproduce it: #113.
I’ll look into this first and come back afterwards.

[MrGuin]

PostWriteCc is skipped on other cores when catalog_entry is nullptr on the first core, which causes the write_req_ on SchemaCntl object is not cleared. I have fixed it and am now verifying if it still occurs.