From 991d6fd8a12def52c8a0581fe0496578faf44b3a Mon Sep 17 00:00:00 2001 From: Minghao Li Date: Tue, 19 Jul 2022 17:20:59 +0800 Subject: [PATCH] refactor(sync): add trace log --- source/libs/sync/src/syncElection.c | 2 +- source/libs/sync/src/syncMain.c | 28 ++++++++++-------- source/libs/sync/src/syncRequestVote.c | 41 ++++++++++++++++++++++++-- 3 files changed, 56 insertions(+), 15 deletions(-) diff --git a/source/libs/sync/src/syncElection.c b/source/libs/sync/src/syncElection.c index 6dcbb598ae..3c4b59ce06 100644 --- a/source/libs/sync/src/syncElection.c +++ b/source/libs/sync/src/syncElection.c @@ -125,7 +125,7 @@ int32_t syncNodeRequestVote(SSyncNode* pSyncNode, const SRaftId* destRaftId, con syncUtilU642Addr(destRaftId->addr, host, sizeof(host), &port); sDebug("vgId:%d, send sync-request-vote to %s:%d, {term:%" PRIu64 ", last-index:%" PRId64 ", last-term:%" PRIu64 "}", - pSyncNode->vgId, host, port, pMsg->term, pMsg->lastLogTerm, pMsg->lastLogIndex); + pSyncNode->vgId, host, port, pMsg->term, pMsg->lastLogIndex, pMsg->lastLogTerm); } while (0); SRpcMsg rpcMsg; diff --git a/source/libs/sync/src/syncMain.c b/source/libs/sync/src/syncMain.c index e11f610dd4..7f85f0979f 100644 --- a/source/libs/sync/src/syncMain.c +++ b/source/libs/sync/src/syncMain.c @@ -1539,13 +1539,13 @@ void syncNodeEventLog(const SSyncNode* pSyncNode, char* str) { if (pSyncNode != NULL && pSyncNode->pRaftCfg != NULL && pSyncNode->pRaftStore != NULL) { snprintf(logBuf, sizeof(logBuf), "vgId:%d, sync %s %s, term:%" PRIu64 ", commit:%" PRId64 ", first:%" PRId64 ", last:%" PRId64 - ", snapshot:%" PRId64 + ", snapshot:%" PRId64 ", snapshot-term:%" PRIu64 ", standby:%d, " "strategy:%d, batch:%d, " "replica-num:%d, " "lconfig:%" PRId64 ", changing:%d, restore:%d, %s", pSyncNode->vgId, syncUtilState2String(pSyncNode->state), str, pSyncNode->pRaftStore->currentTerm, - pSyncNode->commitIndex, logBeginIndex, logLastIndex, snapshot.lastApplyIndex, + pSyncNode->commitIndex, logBeginIndex, logLastIndex, snapshot.lastApplyIndex, snapshot.lastApplyTerm, pSyncNode->pRaftCfg->isStandBy, pSyncNode->pRaftCfg->snapshotStrategy, pSyncNode->pRaftCfg->batchSize, pSyncNode->replicaNum, pSyncNode->pRaftCfg->lastConfigIndex, pSyncNode->changing, pSyncNode->restoreFinish, printStr); @@ -1561,13 +1561,13 @@ void syncNodeEventLog(const SSyncNode* pSyncNode, char* str) { if (pSyncNode != NULL && pSyncNode->pRaftCfg != NULL && pSyncNode->pRaftStore != NULL) { snprintf(s, len, "vgId:%d, sync %s %s, term:%" PRIu64 ", commit:%" PRId64 ", first:%" PRId64 ", last:%" PRId64 - ", snapshot:%" PRId64 + ", snapshot:%" PRId64 ", snapshot-term:%" PRIu64 ", standby:%d, " "strategy:%d, batch:%d, " "replica-num:%d, " "lconfig:%" PRId64 ", changing:%d, restore:%d, %s", pSyncNode->vgId, syncUtilState2String(pSyncNode->state), str, pSyncNode->pRaftStore->currentTerm, - pSyncNode->commitIndex, logBeginIndex, logLastIndex, snapshot.lastApplyIndex, + pSyncNode->commitIndex, logBeginIndex, logLastIndex, snapshot.lastApplyIndex, snapshot.lastApplyTerm, pSyncNode->pRaftCfg->isStandBy, pSyncNode->pRaftCfg->snapshotStrategy, pSyncNode->pRaftCfg->batchSize, pSyncNode->replicaNum, pSyncNode->pRaftCfg->lastConfigIndex, pSyncNode->changing, pSyncNode->restoreFinish, printStr); @@ -1608,14 +1608,16 @@ void syncNodeErrorLog(const SSyncNode* pSyncNode, char* str) { if (pSyncNode != NULL && pSyncNode->pRaftCfg != NULL && pSyncNode->pRaftStore != NULL) { snprintf(logBuf, sizeof(logBuf), "vgId:%d, sync %s %s, term:%" PRIu64 ", commit:%" PRId64 ", first:%" PRId64 ", last:%" PRId64 - ", snapshot:%" PRId64 + ", snapshot:%" PRId64 ", snapshot-term:%" PRIu64 ", standby:%d, " + "strategy:%d, batch:%d, " "replica-num:%d, " "lconfig:%" PRId64 ", changing:%d, restore:%d, %s", pSyncNode->vgId, syncUtilState2String(pSyncNode->state), str, pSyncNode->pRaftStore->currentTerm, - pSyncNode->commitIndex, logBeginIndex, logLastIndex, snapshot.lastApplyIndex, - pSyncNode->pRaftCfg->isStandBy, pSyncNode->replicaNum, pSyncNode->pRaftCfg->lastConfigIndex, - pSyncNode->changing, pSyncNode->restoreFinish, printStr); + pSyncNode->commitIndex, logBeginIndex, logLastIndex, snapshot.lastApplyIndex, snapshot.lastApplyTerm, + pSyncNode->pRaftCfg->isStandBy, pSyncNode->pRaftCfg->snapshotStrategy, pSyncNode->pRaftCfg->batchSize, + pSyncNode->replicaNum, pSyncNode->pRaftCfg->lastConfigIndex, pSyncNode->changing, + pSyncNode->restoreFinish, printStr); } else { snprintf(logBuf, sizeof(logBuf), "%s", str); } @@ -1627,14 +1629,16 @@ void syncNodeErrorLog(const SSyncNode* pSyncNode, char* str) { if (pSyncNode != NULL && pSyncNode->pRaftCfg != NULL && pSyncNode->pRaftStore != NULL) { snprintf(s, len, "vgId:%d, sync %s %s, term:%" PRIu64 ", commit:%" PRId64 ", first:%" PRId64 ", last:%" PRId64 - ", snapshot:%" PRId64 + ", snapshot:%" PRId64 ", snapshot-term:%" PRIu64 ", standby:%d, " + "strategy:%d, batch:%d, " "replica-num:%d, " "lconfig:%" PRId64 ", changing:%d, restore:%d, %s", pSyncNode->vgId, syncUtilState2String(pSyncNode->state), str, pSyncNode->pRaftStore->currentTerm, - pSyncNode->commitIndex, logBeginIndex, logLastIndex, snapshot.lastApplyIndex, - pSyncNode->pRaftCfg->isStandBy, pSyncNode->replicaNum, pSyncNode->pRaftCfg->lastConfigIndex, - pSyncNode->changing, pSyncNode->restoreFinish, printStr); + pSyncNode->commitIndex, logBeginIndex, logLastIndex, snapshot.lastApplyIndex, snapshot.lastApplyTerm, + pSyncNode->pRaftCfg->isStandBy, pSyncNode->pRaftCfg->snapshotStrategy, pSyncNode->pRaftCfg->batchSize, + pSyncNode->replicaNum, pSyncNode->pRaftCfg->lastConfigIndex, pSyncNode->changing, + pSyncNode->restoreFinish, printStr); } else { snprintf(s, len, "%s", str); } diff --git a/source/libs/sync/src/syncRequestVote.c b/source/libs/sync/src/syncRequestVote.c index a6ca0e6d78..1e6e05099c 100644 --- a/source/libs/sync/src/syncRequestVote.c +++ b/source/libs/sync/src/syncRequestVote.c @@ -159,16 +159,53 @@ static bool syncNodeOnRequestVoteLogOK(SSyncNode* pSyncNode, SyncRequestVote* pM SyncIndex myLastIndex = syncNodeGetLastIndex(pSyncNode); if (myLastTerm == SYNC_TERM_INVALID) { + do { + char logBuf[128]; + snprintf(logBuf, sizeof(logBuf), + "logok:0, {my-lterm:%" PRIu64 ", my-lindex:%" PRId64 ", recv-lterm:%" PRIu64 ", recv-lindex:%" PRId64 + ", recv-term:%" PRIu64 "}", + myLastTerm, myLastIndex, pMsg->lastLogTerm, pMsg->lastLogIndex, pMsg->term); + syncNodeEventLog(pSyncNode, logBuf); + } while (0); + return false; } if (pMsg->lastLogTerm > myLastTerm) { + do { + char logBuf[128]; + snprintf(logBuf, sizeof(logBuf), + "logok:1, {my-lterm:%" PRIu64 ", my-lindex:%" PRId64 ", recv-lterm:%" PRIu64 ", recv-lindex:%" PRId64 + ", recv-term:%" PRIu64 "}", + myLastTerm, myLastIndex, pMsg->lastLogTerm, pMsg->lastLogIndex, pMsg->term); + syncNodeEventLog(pSyncNode, logBuf); + } while (0); + return true; } + if (pMsg->lastLogTerm == myLastTerm && pMsg->lastLogIndex >= myLastIndex) { + do { + char logBuf[128]; + snprintf(logBuf, sizeof(logBuf), + "logok:1, {my-lterm:%" PRIu64 ", my-lindex:%" PRId64 ", recv-lterm:%" PRIu64 ", recv-lindex:%" PRId64 + ", recv-term:%" PRIu64 "}", + myLastTerm, myLastIndex, pMsg->lastLogTerm, pMsg->lastLogIndex, pMsg->term); + syncNodeEventLog(pSyncNode, logBuf); + } while (0); + return true; } + do { + char logBuf[128]; + snprintf(logBuf, sizeof(logBuf), + "logok:0, {my-lterm:%" PRIu64 ", my-lindex:%" PRId64 ", recv-lterm:%" PRIu64 ", recv-lindex:%" PRId64 + ", recv-term:%" PRIu64 "}", + myLastTerm, myLastIndex, pMsg->lastLogTerm, pMsg->lastLogIndex, pMsg->term); + syncNodeEventLog(pSyncNode, logBuf); + } while (0); + return false; } @@ -224,8 +261,8 @@ int32_t syncNodeOnRequestVoteSnapshotCb(SSyncNode* ths, SyncRequestVote* pMsg) { uint16_t port; syncUtilU642Addr(pMsg->srcId.addr, host, sizeof(host), &port); snprintf(logBuf, sizeof(logBuf), - "recv sync-request-vote from %s:%d, term:%" PRIu64 ", lindex:%" PRId64 ", lterm:%" PRIu64 - ", reply-grant:%d", + "recv sync-request-vote from %s:%d, {term:%" PRIu64 ", lindex:%" PRId64 ", lterm:%" PRIu64 + ", reply-grant:%d}", host, port, pMsg->term, pMsg->lastLogIndex, pMsg->lastLogTerm, pReply->voteGranted); syncNodeEventLog(ths, logBuf); } while (0); -- GitLab