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

...
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

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
...

(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}

(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}