Skip to content

Issues found in SH test #808

Closed
Closed
Issues found in SH test#808

Description

@Besroy
Besroy
opened on Sep 23, 2025

1. Crash During Graceful Shutdown

This issue occurs during a corner case in the graceful shutdown process:
When the system receives a SIGTERM, the SM begins shutting down by stopping the RaftReplService and resetting m_msg_mgr. However, stopping the RaftReplService does not terminate the fetch reaper thread immediately. This thread is only stopped during the destruction of the replication service. This leads to the following sequence of events:

  1. A follower handles a Raft event and identifies data that needs to be fetched, adding it to the fetch queue.
  2. The follower receives SIGTERM and begins the graceful shutdown process, resetting m_msg_mgr.
  3. During the reset, the gRPC client is destroyed. At the same time, the follower receives a fetch response and attempts to write data, causing a crash.

Related Logs:

[09/21/25 00:25:59.054] [storage_mgr] [warning] [76] [main.cpp:75:handle] SIGNAL: Terminated
[09/21/25 00:25:59.054] [storage_mgr] [info] [15] [hs_homeobject.cpp:395:shutdown] start shutting down HomeObject
[09/21/25 00:25:59.054] [storage_mgr] [info] [15] [hs_homeobject.cpp:413:shutdown] start shutting down HomeStore
[09/21/25 00:25:59.054] [storage_mgr] [info] [15] [homestore.cpp:324:shutdown] Homestore shutdown is started
[09/21/25 00:25:59.054] [storage_mgr] [info] [15] [resource_mgr.cpp:34:stop] Cancel resource manager timer.
[09/21/25 00:25:59.054] [storage_mgr] [info] [15] [iomgr_timer.cpp:126:operator()] Removing recurring global timer fd 65 device
[09/21/25 00:25:59.055] [storage_mgr] [info] [15] [service.cpp:187:shutdown] MessagingService shutdown started.
[09/21/25 00:25:59.125] [storage_mgr] [debug] [74] [raft_repl_service.cpp:635:fetch_pending_data] Reaper Thread: Checking pending fetch queue, current batch size=1
[09/21/25 00:25:59.125] [storage_mgr] [debug] [74] [raft_repl_service.cpp:643:fetch_pending_data] Reaper Thread: Processing fetch request batch of size=1
[09/21/25 00:25:59.125] [storage_mgr] [debug] [74] [raft_repl_dev.cpp:1205:fetch_data_from_remote] [traceID=n/a] [rdev0:e8dfda0a-e9bc-4e8e-8aba-07a6a6958ebb] Data Channel : FetchData from remote: rreq.size=1, my server_id=382253746
[09/21/25 00:25:59.125] [storage_mgr] [trace] [74] [raft_repl_dev.cpp:1222:fetch_data_from_remote] [traceID=11111953329465706830] [rdev0:e8dfda0a-e9bc-4e8e-8aba-07a6a6958ebb] Fetching data from originator=1281565207, remote: rreq=[repl_key=[server=1281565207, term=11, dsn=4719, hash=1281568883], lsn=-1 state=[BLK_ALLOCATED | ] m_headersize=48 m_keysize=8 is_proposer=false local_blkid=[[{blk#=1 count=4097 chunk=210},] ] remote_blkid=[{blk#=1 count=4097 chunk=210},]], remote_blkid=[{blk#=1 count=4097 chunk=210},], my server_id=382253746
[09/21/25 00:25:59.257] [storage_mgr] [debug] [19] [raft_repl_dev.cpp:1405:handle_fetch_data_response] [traceID=11111953329465706830] [rdev0:e8dfda0a-e9bc-4e8e-8aba-07a6a6958ebb] Data Channel: Handling fetched data for rreq=[dsn=4719 term=11 lsn=-1 op=HS_DATA_LINKED local_blkid=[[{blk#=1 count=4097 chunk=210},] ] state=[BLK_ALLOCATED | ]], data_size: 16781312, total_size: 16781312, local_blkid: [{blk#=1 count=4097 chunk=210},]
[09/21/25 00:25:59.260] [storage_mgr] [trace] [66] [common.cpp:176:set_lsn] [traceID=11111953329465706830] Setting lsn=4728 for request=repl_key=[server=1281565207, term=11, dsn=4719, hash=1281568883], lsn=4728 state=[BLK_ALLOCATED | DATA_RECEIVED | ] m_headersize=48 m_keysize=8 is_proposer=false local_blkid=[[{blk#=1 count=4097 chunk=210},] ] remote_blkid=[{blk#=1 count=4097 chunk=210},]
[09/21/25 00:25:59.260] [storage_mgr] [trace] [66] [repl_log_store.cpp:22:append] [traceID=11111953329465706830] [rdev0:e8dfda0a-e9bc-4e8e-8aba-07a6a6958ebb] Raft Channel: Received append log entry rreq=[dsn=4719 term=11 lsn=4728 op=HS_DATA_LINKED local_blkid=[[{blk#=1 count=4097 chunk=210},] ] state=[BLK_ALLOCATED | DATA_RECEIVED | LOG_RECEIVED | ]]
[09/21/25 00:25:59.260] [storage_mgr] [trace] [66] [raft_state_machine.cpp:192:pre_commit_ext] [traceID=11111953329465706830] [rdev0:e8dfda0a-e9bc-4e8e-8aba-07a6a6958ebb] Precommit rreq=[dsn=4719 term=11 lsn=4728 op=HS_DATA_LINKED local_blkid=[[{blk#=1 count=4097 chunk=210},] ] state=[BLK_ALLOCATED | DATA_RECEIVED | LOG_RECEIVED | ]]
[09/21/25 00:25:59.295] [storage_mgr] [debug] [19] [raft_repl_dev.cpp:1423:handle_fetch_data_response] [traceID=11111953329465706830] [rdev0:e8dfda0a-e9bc-4e8e-8aba-07a6a6958ebb] Data Channel: the sha256 value of the data received in handle_fetch_data_response for rreq=[dsn=4719 term=11 lsn=4728 op=HS_DATA_LINKED local_blkid=[[{blk#=1 count=4097 chunk=210},] ] state=[BLK_ALLOCATED | DATA_RECEIVED | LOG_RECEIVED | ]] is 4343271627665467149
[09/21/25 00:25:59.295] [storage_mgr] [critical] [19] [raft_repl_dev.cpp:1441:operator()] [rdev0:e8dfda0a-e9bc-4e8e-8aba-07a6a6958ebb] Error in writing data
[09/21/25 00:25:59.309] [storage_mgr] [critical] [19] [stacktrace.cpp:133:crash_handler]
 * ****Received fatal SIGNAL : SIGABRT(6)       PID : 15
[09/21/25 00:25:59.309] [storage_mgr] [critical] [19] Thread num: 132436650354304 entered exit handler

2. Crash in become_leader Callback

This issue arises due to an assumption in the become_leader callback that the leader is always elected from a follower state. However, under certain conditions, this assumption is violated:

  • Scenario:
    1. A node in term 5 times out and initiates a pre-vote.
    2. The node receives pre-vote requests from other nodes and grants them.
    3. Another node is elected as the leader, increasing the term to 6. The original node becomes a follower and updates its term to 6.
    4. The original node receives responses from its earlier pre-vote, increments its term to 7, and initiates a vote.
    5. The node times out again in term 7 and initiates another pre-vote.
    6. The node is elected as the leader in term 7, but the pre-vote from step 5 completes, causing the term to increment to 8, and another vote is initiated.
    7. The node is elected as the leader in term 8.

Related Logs:

[09/20/25 08:21:00.121266] [I] [66] [handle_timeout.cxx:300:handle_election_timeout] [ELECTION TIMEOUT] current role: follower, log last term 2, state term 5, target p 64, my p 66, hb dead, pre-vote NOT done [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:00.121275] [I] [66] [handle_timeout.cxx:309:handle_election_timeout] pre-vote term (3) is different, reset it to 5 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:00.121294] [I] [66] [handle_vote.cxx:145:request_prevote] [PRE-VOTE INIT] my id 1196076733, my role candidate, term 5, log idx 20309, log term 2, priority (target 64 / mine 66) [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
HB dead [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:00.952550] [I] [69] [handle_vote.cxx:468:handle_prevote_req] pre-vote decision: O (grant) [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
HB dead [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:01.032993] [I] [68] [handle_vote.cxx:468:handle_prevote_req] pre-vote decision: O (grant) [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:01.099561] [I] [69] [raft_server.cxx:1479:become_follower] [BECOME FOLLOWER] term 6 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:01.099633] [I] [69] [handle_priority.cxx:222:decay_target_priority] [PRIORITY] decay, target 64 -> 52, mine 66 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
priority: target 52 / mine 66, voted_for -1 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:01.099663] [I] [69] [handle_vote.cxx:384:handle_vote_req] decision: X (deny), term 6 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:01.181253] [I] [64] [handle_vote.cxx:508:handle_prevote_resp] [PRE-VOTE RESP] peer 1312695038 (O), term 5, resp term 5, my role follower, dead 2, live 0, abandoned 0, num voting members 3, quorum 2 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:01.181275] [I] [64] [handle_vote.cxx:518:handle_prevote_resp] [PRE-VOTE DONE] SUCCESS, term 5 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:01.181283] [I] [64] [handle_vote.cxx:523:handle_prevote_resp] [PRE-VOTE DONE] initiate actual vote [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:01.273696] [I] [64] [handle_vote.cxx:264:request_vote] [VOTE INIT] my id 1196076733, my role candidate, term 7, log idx 20309, log term 2, priority (target 52 / mine 66) [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:02.760193] [I] [64] [handle_vote.cxx:508:handle_prevote_resp] [PRE-VOTE RESP] peer 736844815 (O), term 5, resp term 5, my role candidate, dead 3, live 0, abandoned 0, num voting members 3, quorum 2 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:02.760205] [I] [64] [handle_vote.cxx:518:handle_prevote_resp] [PRE-VOTE DONE] SUCCESS, term 5 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:02.760213] [I] [64] [handle_vote.cxx:534:handle_prevote_resp] [PRE-VOTE DONE] actual vote is already initiated, do nothing [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:05.554157] [I] [66] [handle_priority.cxx:222:decay_target_priority] [PRIORITY] decay, target 52 -> 42, mine 66 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:05.554171] [I] [66] [handle_timeout.cxx:300:handle_election_timeout] [ELECTION TIMEOUT] current role: candidate, log last term 2, state term 7, target p 42, my p 66, hb dead, pre-vote done [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:05.554180] [I] [66] [handle_timeout.cxx:309:handle_election_timeout] pre-vote term (5) is different, reset it to 7 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:05.554201] [I] [66] [handle_vote.cxx:145:request_prevote] [PRE-VOTE INIT] my id 1196076733, my role candidate, term 7, log idx 20309, log term 2, priority (target 42 / mine 66) [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.042188] [I] [64] [handle_vote.cxx:415:handle_vote_resp] [VOTE RESP] peer 1312695038 (O), resp term 7, my role candidate, granted 2, responded 2, num voting members 3, quorum 2 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.042200] [I] [64] [handle_vote.cxx:424:handle_vote_resp] Server is elected as leader for term 7 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.042219] [I] [64] [raft_server.cxx:1096:become_leader] number of pending commit elements: 0 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.042232] [I] [64] [raft_server.cxx:1110:become_leader] state machine commit index 20309, precommit index 20309, last log index 20309 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.042634] [I] [64] [raft_server.cxx:1164:become_leader] [BECOME LEADER] appended new config at 20310 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.058246] [I] [64] [handle_vote.cxx:427:handle_vote_resp]   === LEADER (term 7) === [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.154145] [I] [64] [handle_vote.cxx:508:handle_prevote_resp] [PRE-VOTE RESP] peer 736844815 (O), term 7, resp term 7, my role leader, dead 2, live 0, abandoned 0, num voting members 3, quorum 2 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.154160] [I] [64] [handle_vote.cxx:518:handle_prevote_resp] [PRE-VOTE DONE] SUCCESS, term 7 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.154167] [I] [64] [handle_vote.cxx:523:handle_prevote_resp] [PRE-VOTE DONE] initiate actual vote [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.154571] [I] [64] [handle_vote.cxx:264:request_vote] [VOTE INIT] my id 1196076733, my role candidate, term 8, log idx 20310, log term 7, priority (target 42 / mine 66) [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.219994] [I] [64] [handle_vote.cxx:415:handle_vote_resp] [VOTE RESP] peer 736844815 (O), resp term 8, my role candidate, granted 2, responded 2, num voting members 3, quorum 2 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.220005] [I] [64] [handle_vote.cxx:424:handle_vote_resp] Server is elected as leader for term 8 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.220024] [I] [64] [raft_server.cxx:1096:become_leader] number of pending commit elements: 0 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.220047] [I] [64] [raft_server.cxx:1110:become_leader] state machine commit index 20309, precommit index 20310, last log index 20310 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.220081] [I] [64] [raft_server.cxx:1147:become_leader] found uncommitted config at 20310, size 178 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]
[09/20/25 08:21:06.220483] [I] [64] [raft_server.cxx:1164:become_leader] [BECOME LEADER] appended new config at 20311 [group=c527e3a3-3cd1-4bb1-947b-4c37570cd6ab]

Activity

  1. Besroy commented on Sep 23, 2025

    @Besroy
    Besroy
    on Sep 23, 2025
    ContributorAuthor

    #806

  2. JacksonYao287 commented on Oct 23, 2025

    @JacksonYao287
    JacksonYao287
    on Oct 23, 2025
    Member

    resolved

  3. JacksonYao287
    closed this as completedon Oct 23, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions