During the eloqdoc jepsen test, log replay failed to complete.

[yangsw26]

EloqDoc WITH_LOG_STATE: rocksdb_cloud using EloqStore Cloud as the storage.

The server status before been killed:

...
I20251212 20:18:31.095757 690779 tx_operation.cpp:4215] Split Flush transaction prepare acquire all, range id 2883, txn: 217978
I20251212 20:18:31.358275 690779 tx_operation.cpp:4265] Split Flush transaction write prepare log, range id 2883, txn: 217978
I20251212 20:18:31.368647 690779 tx_operation.cpp:4326] Split Flush transaction install dirty range, range id 2883, txn: 217978
I20251212 20:18:31.369580 690779 tx_operation.cpp:4369] Split Flush transaction unlock cluster config, range id 2883, txn: 217978
I20251212 20:18:31.369612 690779 tx_operation.cpp:4465] Split Flush transaction data sync, range id 2883, txn: 217978
I20251212 20:20:29.333606 690779 tx_operation.cpp:4497] Split Flush transaction lock cluster config, range id 2883, txn: 217978
I20251212 20:20:29.333736 690779 tx_operation.cpp:4223] Split Flush transaction commit acqurie all, range id 2883, txn: 217978
I20251212 20:20:29.443446 690779 tx_operation.cpp:4608] Split Flush transaction write commit log, range id 2883, txn: 217978
I20251212 20:20:29.703727 690779 tx_operation.cpp:4690] Split Flush transaction upsert new range spec, range id 2883, txn: 217978
I20251212 20:20:32.722615 690779 tx_operation.cpp:4722] Split Flush transaction post all lock, range id 2883, txn: 217978
I20251212 20:20:32.812831 690779 tx_operation.cpp:4833] Split Flush transaction unlock cluster config, range id 2883, txn: 217978
I20251212 20:20:32.813019 690779 tx_operation.cpp:4428] Split Flush transaction clean old range data in kv store, range id 2883, txn: 217978
...
...
I20251212 20:29:17.372906 690776 tx_operation.cpp:4223] Split Flush transaction commit acqurie all, range id 3684, txn: 12885243330
I20251212 20:29:17.608042 690776 tx_operation.cpp:4608] Split Flush transaction write commit log, range id 3684, txn: 12885243330
I20251212 20:29:18.010238 690776 tx_operation.cpp:4690] Split Flush transaction upsert new range spec, range id 3684, txn: 12885243330
I20251212 20:29:21.847121 690776 tx_operation.cpp:4722] Split Flush transaction post all lock, range id 3684, txn: 12885243330
I20251212 20:29:22.116184 690776 tx_operation.cpp:4833] Split Flush transaction unlock cluster config, range id 3684, txn: 12885243330
I20251212 20:29:22.127562 690776 tx_operation.cpp:4428] Split Flush transaction clean old range data in kv store, range id 3684, txn: 12885243330
I20251212 20:29:56.749011 690776 log_state.h:1204] write split range op, txn: 12885243330, range table name: tpcc.STOCK, stage: 1, commit_ts: 1765542282669911
...
W20251212 20:33:15.847599 690861 cc_shard.cpp:923] orphan lock detected, lock holding txn: 12885308384, try to recover
I20251212 20:33:15.847620 690861 cc_shard.cpp:914] Txn #8590229601 locks tpcc.NEW_ORDER, lock type: 3
I20251212 20:33:15.847631 690861 cc_shard.cpp:914] Txn #8590229601 locks tpcc.STOCK*$$S_W_ID_1_S_I_ID_1_S_QUANTITY_1, lock type: 1
I20251212 20:33:15.847641 690861 cc_shard.cpp:914] Txn #8590229601 locks tpcc.STOCK*$$S_I_ID_1, lock type: 1
W20251212 20:33:15.847652 690861 cc_shard.cpp:923] orphan lock detected, lock holding txn: 8590229601, try to recover
I20251212 20:33:15.856128 690828 cc_request.h:3153] ccs 0 memory usage report, committed 4237689952, allocated 3185946552, frag ratio 25 , heap full: 0
I20251212 20:33:15.856323 690828 cc_request.h:3153] ccs 1 memory usage report, committed 4228914944, allocated 3185637600, frag ratio 25 , heap full: 0
I20251212 20:33:15.856338 690828 cc_request.h:3153] ccs 2 memory usage report, committed 4177489376, allocated 3147949016, frag ratio 25 , heap full: 0
I20251212 20:33:15.856350 690828 cc_request.h:3153] ccs 3 memory usage report, committed 4221546080, allocated 3187011080, frag ratio 25 , heap full: 0
I20251212 20:33:15.856365 690828 local_cc_shards.h:486] Table range memory report: allocated 555950360, committed 557120544, full: 0
I20251212 20:33:15.856385 690828 checkpointer.cpp:229] Begin checkpoint of node group #0 with timestamp: 1765542750230026. The memory usage of node is: 12408734 KB.
W20251212 20:33:16.755290 690826 log_agent.cpp:176] Fail to refresh_leader : [192.168.122.25:8082:0:0] [E1008]Reached timeout=500ms @192.168.122.25:8082
W20251212 20:33:16.927217 690776 tx_operation.cpp:982] Write Log Request result unknown, remain retrying time: 1, tx_number: 12885308407
I20251212 20:33:21.909232 690778 log_state_rocksdb_cloud_impl.cpp:747] tx: 4295371878 not found in log state

The server status when restart:

I20251212 20:36:17.862164 738586 data_substrate.cpp:129] DataSubstrate initialized (config loaded)
...
I20251212 20:36:31.734411 738605 cc_node.cpp:382] CC node 0 becomes the leader of ng#0. Term: 3
...
I20251212 20:36:31.762967 738605 log_instance.cpp:865] ReplayLogRequest cc_ng_id: 0 term: 3 ip: 192.168.122.25 port: 8083 term match? yes
I20251212 20:36:31.762979 738605 log_instance.cpp:872] shipping log records to: 192.168.122.25 8083
I20251212 20:36:31.762991 738605 log_instance.cpp:884] start replaying from ts 1765539875797072
I20251212 20:36:31.763113 738605 log_state_rocksdb_cloud_impl.cpp:662] cluster_scale_list size: 0
I20251212 20:36:31.763188 738605 log_state_rocksdb_cloud_impl.cpp:666] schema_log_list size: 0
I20251212 20:36:31.822165 738605 log_state_rocksdb_cloud_impl.cpp:670] split_range_op_list size: 2
...
I20251212 20:36:42.921087 738604 tx_execution.cpp:1706] Recovering split flush tx 217978 on table tpcc.ORDERS, range id 2883
I20251212 20:36:44.596918 738602 tx_execution.cpp:1706] Recovering split flush tx 12885243330 on table tpcc.STOCK, range id 3684
...

NOTE: The recovery transactions for these two range splits have been unable to forward because node replay has not yet completed.

(gdb) bt
#0  txservice::fault::RecoveryService::WaitAndClearRequests (this=0x2db4217b400, stream_id=<optimized out>, mux=..., on_fly_cnt_=..., status=..., recovery_error=<optimized out>, waiting_status=<optimized out>)
    at /home/eloq/workspace/eloqdoc/src/mongo/db/modules/eloq/data_substrate/tx_service/src/fault/log_replay_service.cpp:794
eloqdata/eloqdoc#1  0x000077b633d71479 in txservice::fault::RecoveryService::on_closed (this=0x2db4217b400, id=<optimized out>) at /home/eloq/workspace/eloqdoc/src/mongo/db/modules/eloq/data_substrate/tx_service/src/fault/log_replay_service.cpp:763
eloqdata/eloqdoc#2  0x000077b63b3ccb1d in brpc::Stream::Consume (meta=0x2db3f2f0780, iter=...) at /home/eloq/brpc/src/brpc/stream_impl.h:50
eloqdata/eloqdoc#3  0x000077b63b2057e0 in bthread::ExecutionQueueBase::_execute (this=0x2dcb20a4900, head=<optimized out>, high_priority=<optimized out>, niterated=0x0) at /home/eloq/brpc/src/bthread/execution_queue.cpp:264
eloqdata/eloqdoc#4  0x000077b63b20682b in bthread::ExecutionQueueBase::_execute_tasks (arg=<optimized out>) at /home/eloq/brpc/src/bthread/execution_queue.cpp:151
eloqdata/eloqdoc#5  0x000077b63b225327 in bthread::TaskGroup::task_runner (skip_remained=<optimized out>) at /home/eloq/brpc/src/bthread/task_group.cpp:384
eloqdata/eloqdoc#6  0x000077b63b204b71 in bthread_make_fcontext () from /mnt/ssd/eloq/jepsen-eloqdoc-test/eloqdoc-cloud/bin/../lib/libbrpc.so
eloqdata/eloqdoc#7  0x0000000000000000 in ?? ()
(gdb) info local
on_fly_cnt = 602
lk = {_M_device = 0x0, _M_owns = false}

CcShards status:

(gdb) p ((txservice::CcShard*)(*(void**)0x2db43ff0658))->cc_queue_size_
$29 = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 2}, static is_always_lock_free = true}
(gdb) p ((txservice::CcShard*)(*(void**)0x2db43ff0650))->cc_queue_size_
$30 = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 2}, static is_always_lock_free = true}
(gdb) p ((txservice::CcShard*)(*(void**)0x2db43ff0648))->cc_queue_size_
$31 = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 2}, static is_always_lock_free = true}
(gdb) p ((txservice::CcShard*)(*(void**)0x2db43ff0640))->cc_queue_size_
$32 = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 2}, static is_always_lock_free = true}

[coderabbitai]

📝 CodeRabbit Plan Mode

Generate an implementation plan and prompts that you can use with your favorite coding agent.

• Create Plan

Examples

• Example 1
• Example 2

🔗 Similar Issues

Possible Duplicates

• jepsen test fail when populate warehouse eloqdoc#241

Related Issues

• [Bug] EloqDoc hangs on jepsen test eloqdoc#129
• test: Flushdb failed lead to jepsen test fail. store_handler#91
• https://github.com/eloqdata/tx_service/issues/159
• [Bug]: Crash when execute remote blocked request check. #239
• [Bug]: Deadlock when add concurrently eloqkv#199
• [Bug]: ReplayLogCc Assertion `op_type == OperationType::Insert || op_type == OperationType::Update || op_type == OperationType::Delete' failed #53
• [Bug]: flushdb failed at acquire write intent in eloqkv jepsen three node group test. eloqkv#221

🔗 Related PRs

#139 - Improve hash-partition data sync scheduling and memory control. [merged]
eloqdata/eloqdoc#224 - Replace USE_ROCKSDB_LOG_STATE and WITH_ROCKSDB_CLOUD compile flags [merged]
eloqdata/store_handler#122 - Convert txservice cluster config to dss_config [merged]
#241 - Merge unfull flush tasks [merged]
#250 - fix bug and refactor init process [merged]

👤 Suggested Assignees

• yi-xmu
• lokax
• githubzilla
• liunyl
• xiexiaoy

---

🧪 Issue enrichment is currently in early access.

To disable automatic issue enrichment, add the following to your .coderabbit.yaml:

issue_enrichment:
  auto_enrich:
    enabled: false

[coderabbitai]

📝 CodeRabbit Plan Mode

Generate an implementation plan and prompts that you can use with your favorite coding agent.

• Create Plan

Examples

• Example 1
• Example 2

_{You can configure auto-planning by selecting labels in the issue_enrichment configuration.}

🔗 Similar Issues

Possible Duplicates

• https://github.com/eloqdata/tx_service/issues/159

Related Issues

• [Bug] EloqDoc hangs on jepsen test eloqdoc#129
• test: Flushdb failed lead to jepsen test fail. store_handler#91
• jepsen test fail when populate warehouse eloqdoc#241
• Rocksdb Cloud operation failed with error: Timeout was reached store_handler#86
• https://github.com/eloqdata/eloqdoc/issues/367
• [Bug]: Crash when execute remote blocked request check. #239
• [Bug]: Deadlock when add concurrently eloqkv#199
• [Bug]: ReplayLogCc Assertion `op_type == OperationType::Insert || op_type == OperationType::Update || op_type == OperationType::Delete' failed #53
• [Bug]: flushdb failed at acquire write intent in eloqkv jepsen three node group test. eloqkv#221

🔗 Related PRs

#139 - Improve hash-partition data sync scheduling and memory control. [merged]
eloqdata/eloqdoc#224 - Replace USE_ROCKSDB_LOG_STATE and WITH_ROCKSDB_CLOUD compile flags [merged]
eloqdata/store_handler#122 - Convert txservice cluster config to dss_config [merged]
#241 - Merge unfull flush tasks [merged]
#250 - fix bug and refactor init process [merged]

👤 Suggested Assignees

• yi-xmu
• lokax
• githubzilla
• liunyl
• xiexiaoy

---

🧪 Issue enrichment is currently in open beta.

To disable automatic issue enrichment, add the following to your .coderabbit.yaml:

issue_enrichment:
  auto_enrich:
    enabled: false

💬 Have feedback or questions? Drop into our discord or schedule a call!

[MrGuin]

Could be that the memory was full during log replay? The ReplayLogCcs might have been EnqueueWaitListIfMemoryFull, which is why they cannot be seen in CcShard::cc_queue_size_.

[liunyl]

Potential root cause:

Range split tx was replayed first, which puts a barrier on the range that blocks following checkpoint on this range. This can only proceed after log replay is finished.
Then data log started to replay, and was blocked by OOM, so it enqueues itself into waitlist and wait for checkpoint.
Checkpoint cannot flush any data since all data is in the splitting range, which blocks log replay from completing.

[liunyl]

reproduced again on eloqsql
logs after restart. Memory is full but checkpoint cannot proceed to flush data

[time 2026-01-09T21:14:12.730087] [level INFO] [thread 1581186] [cc_request.h:3153] ccs 0 memory usage report, committed 9593294024, allocated 9592553096, frag ratio 0.0077 , heap full: 1
[time 2026-01-09T21:14:12.730158] [level INFO] [thread 1581186] [cc_request.h:3153] ccs 1 memory usage report, committed 316819112, allocated 316290912, frag ratio 0.17 , heap full: 0
[time 2026-01-09T21:14:12.730185] [level INFO] [thread 1581186] [cc_request.h:3153] ccs 2 memory usage report, committed 192010216, allocated 191148632, frag ratio 0.45 , heap full: 0
[time 2026-01-09T21:14:12.730207] [level INFO] [thread 1581186] [cc_request.h:3153] ccs 3 memory usage report, committed 268477952, allocated 268067168, frag ratio 0.15 , heap full: 0
[time 2026-01-09T21:14:12.730229] [level INFO] [thread 1581186] [cc_request.h:3153] ccs 4 memory usage report, committed 301785808, allocated 301390720, frag ratio 0.13 , heap full: 0
[time 2026-01-09T21:14:12.730250] [level INFO] [thread 1581186] [cc_request.h:3153] ccs 5 memory usage report, committed 46561144, allocated 46197104, frag ratio 0.78 , heap full: 0
[time 2026-01-09T21:14:12.730273] [level INFO] [thread 1581186] [cc_request.h:3153] ccs 6 memory usage report, committed 43867016, allocated 43539912, frag ratio 0.75 , heap full: 0
[time 2026-01-09T21:14:12.730293] [level INFO] [thread 1581186] [cc_request.h:3153] ccs 7 memory usage report, committed 41264824, allocated 40960976, frag ratio 0.74 , heap full: 0
[time 2026-01-09T21:14:12.730317] [level INFO] [thread 1581186] [local_cc_shards.h:568] Table range memory report: allocated 1037024, committed 1246448, full: 0
[time 2026-01-09T21:14:12.730362] [level INFO] [thread 1581186] [checkpointer.cpp:229] Begin checkpoint of node group #0 with timestamp: 1767964445834419. The memory usage of node is: 10547020 KB.
[time 2026-01-09T21:14:12.852561] [level WARNING] [thread 1581115] [cc_shard.cpp:998] orphan lock detected, lock holding txn: 21474848158, txn is initiated by this machine, try to recover
[time 2026-01-09T21:14:12.852555] [level WARNING] [thread 1581108] [cc_shard.cpp:998] orphan lock detected, lock holding txn: 21474848158, txn is initiated by this machine, try to recover
[time 2026-01-09T21:14:12.852556] [level WARNING] [thread 1581109] [cc_shard.cpp:998] orphan lock detected, lock holding txn: 21474848158, txn is initiated by this machine, try to recover
[time 2026-01-09T21:14:12.852558] [level WARNING] [thread 1581110] [cc_shard.cpp:998] orphan lock detected, lock holding txn: 21474848158, txn is initiated by this machine, try to recover
[time 2026-01-09T21:14:12.852559] [level WARNING] [thread 1581114] [cc_shard.cpp:998] orphan lock detected, lock holding txn: 21474848158, txn is initiated by this machine, try to recover
[time 2026-01-09T21:14:12.852558] [level WARNING] [thread 1581113] [cc_shard.cpp:998] orphan lock detected, lock holding txn: 21474848158, txn is initiated by this machine, try to recover
[time 2026-01-09T21:14:12.852609] [level INFO] [thread 1581115] [cc_shard.cpp:1034] Txn #21474848158 locks ./tpcc_100/order_line*$$ol_supply_w_id_ranges, lock type: 4
[time 2026-01-09T21:14:12.852705] [level INFO] [thread 1581113] [cc_shard.cpp:1034] Txn #21474848158 locks ./tpcc_100/order_line*$$ol_supply_w_id_ranges, lock type: 4

[yangsw26]

Solution: allow the recovered split flush tx forwarding on the candidate leader node.

[yangsw26]

All related requests need to be allowed to execute on the candidate leader node, such as ReadCc, PostReadCc, and DataSyncScanCc.

[yangsw26]

Similarly, checkpointers should be allowed to execute on candidate leaders.

[yangsw26]

In the current code, the checkpointer is not performed on the candidate leader node. Therefore, even there is no recovering split flush txm, a large amount of data log replay will cause OUT_OF_MEMORY, preventing node recovery from finished.

Related issue: #361