diff --git a/source/dnode/mnode/impl/src/mndSync.c b/source/dnode/mnode/impl/src/mndSync.c index 36f5d31676..d669994128 100644 --- a/source/dnode/mnode/impl/src/mndSync.c +++ b/source/dnode/mnode/impl/src/mndSync.c @@ -475,7 +475,7 @@ int32_t mndInitSync(SMnode *pMnode) { snprintf(syncInfo.path, sizeof(syncInfo.path), "%s%ssync", pMnode->path, TD_DIRSEP); syncInfo.pFsm = mndSyncMakeFsm(pMnode); - mInfo("vgId:1, start to open sync, replica:%d selfIndex:%d", pMgmt->numOfReplicas, pMgmt->selfIndex); + mInfo("vgId:1, start to open mnode sync, replica:%d selfIndex:%d", pMgmt->numOfReplicas, pMgmt->selfIndex); SSyncCfg *pCfg = &syncInfo.syncCfg; pCfg->totalReplicaNum = pMgmt->numOfTotalReplicas; pCfg->replicaNum = pMgmt->numOfReplicas; @@ -502,7 +502,7 @@ int32_t mndInitSync(SMnode *pMnode) { } pMnode->pSdb->sync = pMgmt->sync; - mInfo("mnode-sync is opened, id:%" PRId64, pMgmt->sync); + mInfo("vgId:1, mnode sync is opened, id:%" PRId64, pMgmt->sync); TAOS_RETURN(code); } @@ -606,12 +606,13 @@ int32_t mndSyncPropose(SMnode *pMnode, SSdbRaw *pRaw, int32_t transId) { } void mndSyncStart(SMnode *pMnode) { + mInfo("vgId:1, start to start mnode sync"); SSyncMgmt *pMgmt = &pMnode->syncMgmt; if (syncStart(pMgmt->sync) < 0) { mError("vgId:1, failed to start sync, id:%" PRId64, pMgmt->sync); return; } - mInfo("vgId:1, sync started, id:%" PRId64, pMgmt->sync); + mInfo("vgId:1, mnode sync started, id:%" PRId64, pMgmt->sync); } void mndSyncStop(SMnode *pMnode) { diff --git a/source/dnode/mnode/impl/src/mndTrans.c b/source/dnode/mnode/impl/src/mndTrans.c index 521539759c..63cab4168a 100644 --- a/source/dnode/mnode/impl/src/mndTrans.c +++ b/source/dnode/mnode/impl/src/mndTrans.c @@ -837,6 +837,9 @@ static bool mndCheckTransConflict(SMnode *pMnode, STrans *pNew) { if (pNew->conflict == TRN_CONFLICT_NOTHING) return conflict; + int32_t size = sdbGetSize(pMnode->pSdb, SDB_TRANS); + mInfo("trans:%d, trans hash size %d", pNew->id, size); + while (1) { pIter = sdbFetch(pMnode->pSdb, SDB_TRANS, pIter, (void **)&pTrans); if (pIter == NULL) break; @@ -905,14 +908,14 @@ int32_t mndTransCheckConflict(SMnode *pMnode, STrans *pTrans) { if (pTrans->conflict == TRN_CONFLICT_DB || pTrans->conflict == TRN_CONFLICT_DB_INSIDE) { if (strlen(pTrans->dbname) == 0 && strlen(pTrans->stbname) == 0) { code = TSDB_CODE_MND_TRANS_CONFLICT; - mError("trans:%d, failed to prepare conflict db not set", pTrans->id); + mError("trans:%d, failed to check tran conflict since db not set", pTrans->id); TAOS_RETURN(code); } } if (mndCheckTransConflict(pMnode, pTrans)) { code = TSDB_CODE_MND_TRANS_CONFLICT; - mError("trans:%d, failed to prepare since %s", pTrans->id, tstrerror(code)); + mError("trans:%d, failed to check tran conflict since %s", pTrans->id, tstrerror(code)); TAOS_RETURN(code); } @@ -948,7 +951,7 @@ int32_t mndTransCheckConflictWithCompact(SMnode *pMnode, STrans *pTrans) { if (conflict) { code = TSDB_CODE_MND_TRANS_CONFLICT_COMPACT; - mError("trans:%d, failed to prepare since %s", pTrans->id, tstrerror(code)); + mError("trans:%d, failed to check tran conflict with compact since %s", pTrans->id, tstrerror(code)); TAOS_RETURN(code); } diff --git a/source/libs/sync/inc/syncUtil.h b/source/libs/sync/inc/syncUtil.h index f0bf095935..1606f47592 100644 --- a/source/libs/sync/inc/syncUtil.h +++ b/source/libs/sync/inc/syncUtil.h @@ -113,7 +113,8 @@ void syncLogRecvSyncSnapshotRsp(SSyncNode* pSyncNode, const SyncSnapshotRsp* pMs void syncLogRecvAppendEntries(SSyncNode* pSyncNode, const SyncAppendEntries* pMsg, const char* s); void syncLogSendAppendEntries(SSyncNode* pSyncNode, const SyncAppendEntries* pMsg, const char* s); -void syncLogRecvRequestVote(SSyncNode* pSyncNode, const SyncRequestVote* pMsg, int32_t voteGranted, const char* s); +void syncLogRecvRequestVote(SSyncNode* pSyncNode, const SyncRequestVote* pMsg, int32_t voteGranted, const char* s, + const char* opt); void syncLogSendRequestVote(SSyncNode* pSyncNode, const SyncRequestVote* pMsg, const char* s); void syncLogRecvRequestVoteReply(SSyncNode* pSyncNode, const SyncRequestVoteReply* pMsg, const char* s); diff --git a/source/libs/sync/src/syncMain.c b/source/libs/sync/src/syncMain.c index 92c8127b50..a0236c38b8 100644 --- a/source/libs/sync/src/syncMain.c +++ b/source/libs/sync/src/syncMain.c @@ -61,6 +61,7 @@ static int32_t syncDoLeaderTransfer(SSyncNode* ths, SRpcMsg* pRpcMsg, SSyncRaftE static ESyncStrategy syncNodeStrategy(SSyncNode* pSyncNode); int64_t syncOpen(SSyncInfo* pSyncInfo, int32_t vnodeVersion) { + sInfo("vgId:%d, start to open sync", pSyncInfo->vgId); SSyncNode* pSyncNode = syncNodeOpen(pSyncInfo, vnodeVersion); if (pSyncNode == NULL) { sError("vgId:%d, failed to open sync node", pSyncInfo->vgId); @@ -79,6 +80,7 @@ int64_t syncOpen(SSyncInfo* pSyncInfo, int32_t vnodeVersion) { pSyncNode->hbBaseLine = pSyncInfo->heartbeatMs; pSyncNode->heartbeatTimerMS = pSyncInfo->heartbeatMs; pSyncNode->msgcb = pSyncInfo->msgcb; + sInfo("vgId:%d, sync opened", pSyncInfo->vgId); return pSyncNode->rid; } @@ -91,6 +93,7 @@ int32_t syncStart(int64_t rid) { sError("failed to acquire rid:%" PRId64 " of tsNodeReftId for pSyncNode", rid); TAOS_RETURN(code); } + sInfo("vgId:%d, begin to start sync", pSyncNode->vgId); if ((code = syncNodeRestore(pSyncNode)) < 0) { sError("vgId:%d, failed to restore sync log buffer since %s", pSyncNode->vgId, tstrerror(code)); @@ -103,6 +106,9 @@ int32_t syncStart(int64_t rid) { } syncNodeRelease(pSyncNode); + + sInfo("vgId:%d, sync started", pSyncNode->vgId); + TAOS_RETURN(code); _err: @@ -1370,7 +1376,7 @@ SSyncNode* syncNodeOpen(SSyncInfo* pSyncInfo, int32_t vnodeVersion) { pSyncNode->hbrSlowNum = 0; pSyncNode->tmrRoutineNum = 0; - sNInfo(pSyncNode, "sync open, node:%p electInterval:%d heartbeatInterval:%d heartbeatTimeout:%d", pSyncNode, + sNInfo(pSyncNode, "sync node opened, node:%p electInterval:%d heartbeatInterval:%d heartbeatTimeout:%d", pSyncNode, tsElectInterval, tsHeartbeatInterval, tsHeartbeatTimeout); return pSyncNode; @@ -1434,6 +1440,7 @@ int32_t syncNodeRestore(SSyncNode* pSyncNode) { int32_t syncNodeStart(SSyncNode* pSyncNode) { // start raft + sInfo("vgId:%d, begin to start sync node", pSyncNode->vgId); if (pSyncNode->raftCfg.cfg.nodeInfo[pSyncNode->raftCfg.cfg.myIndex].nodeRole == TAOS_SYNC_ROLE_LEARNER) { syncNodeBecomeLearner(pSyncNode, "first start"); } else { @@ -1453,6 +1460,7 @@ int32_t syncNodeStart(SSyncNode* pSyncNode) { if (ret != 0) { sError("vgId:%d, failed to start ping timer since %s", pSyncNode->vgId, tstrerror(ret)); } + sInfo("vgId:%d, sync node started", pSyncNode->vgId); return ret; } @@ -2034,6 +2042,8 @@ void syncNodeBecomeFollower(SSyncNode* pSyncNode, const char* debugStr) { // reset elect timer syncNodeResetElectTimer(pSyncNode); + + sInfo("vgId:%d, become follower. %s", pSyncNode->vgId, debugStr); } void syncNodeBecomeLearner(SSyncNode* pSyncNode, const char* debugStr) { diff --git a/source/libs/sync/src/syncRequestVote.c b/source/libs/sync/src/syncRequestVote.c index 738e558033..c8e81b13df 100644 --- a/source/libs/sync/src/syncRequestVote.c +++ b/source/libs/sync/src/syncRequestVote.c @@ -91,9 +91,11 @@ int32_t syncNodeOnRequestVote(SSyncNode* ths, const SRpcMsg* pRpcMsg) { SyncRequestVote* pMsg = pRpcMsg->pCont; bool resetElect = false; + syncLogRecvRequestVote(ths, pMsg, -1, "", "recv"); + // if already drop replica, do not process if (!syncNodeInRaftGroup(ths, &pMsg->srcId)) { - syncLogRecvRequestVote(ths, pMsg, -1, "not in my config"); + syncLogRecvRequestVote(ths, pMsg, -1, "not in my config", "process"); TAOS_RETURN(TSDB_CODE_SYN_MISMATCHED_SIGNATURE); } @@ -133,7 +135,7 @@ int32_t syncNodeOnRequestVote(SSyncNode* ths, const SRpcMsg* pRpcMsg) { if (!(!grant || pMsg->term == pReply->term)) return TSDB_CODE_SYN_INTERNAL_ERROR; // trace log - syncLogRecvRequestVote(ths, pMsg, pReply->voteGranted, ""); + syncLogRecvRequestVote(ths, pMsg, pReply->voteGranted, "", "proceed"); syncLogSendRequestVoteReply(ths, pReply, ""); (void)syncNodeSendMsgById(&pReply->destId, ths, &rpcMsg); diff --git a/source/libs/sync/src/syncUtil.c b/source/libs/sync/src/syncUtil.c index a30bd9064f..553560f089 100644 --- a/source/libs/sync/src/syncUtil.c +++ b/source/libs/sync/src/syncUtil.c @@ -470,13 +470,13 @@ void syncLogSendAppendEntries(SSyncNode* pSyncNode, const SyncAppendEntries* pMs pMsg->commitIndex, pMsg->dataLen, s); } -void syncLogRecvRequestVote(SSyncNode* pSyncNode, const SyncRequestVote* pMsg, int32_t voteGranted, - const char* errmsg) { +void syncLogRecvRequestVote(SSyncNode* pSyncNode, const SyncRequestVote* pMsg, int32_t voteGranted, const char* errmsg, + const char* opt) { char statusMsg[64]; snprintf(statusMsg, sizeof(statusMsg), "granted:%d", voteGranted); sNInfo(pSyncNode, - "recv sync-request-vote from dnode:%d, {term:%" PRId64 ", last-index:%" PRId64 ", last-term:%" PRId64 "}, %s", - DID(&pMsg->srcId), pMsg->term, pMsg->lastLogIndex, pMsg->lastLogTerm, + "%s sync-request-vote from dnode:%d, {term:%" PRId64 ", last-index:%" PRId64 ", last-term:%" PRId64 "}, %s", + opt, DID(&pMsg->srcId), pMsg->term, pMsg->lastLogIndex, pMsg->lastLogTerm, (voteGranted != -1) ? statusMsg : errmsg); }