fix/TD-30734-format-log

This commit is contained in:
dmchen 2024-09-03 05:02:07 +00:00
parent b2f2d56c41
commit df8ded28d5
6 changed files with 31 additions and 14 deletions

View File

@ -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) {

View File

@ -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);
}

View File

@ -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);

View File

@ -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) {

View File

@ -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);

View File

@ -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);
}