Clean up debug log level by moving many frequent logs to trace level (#…

…2004) * Clean up debug log level and move most/frequent logs to trace level * Change function call traces to trace log level
kaspanet · Apr 3, 2022 · 80879ca · 80879ca
1 parent 71afc62
commit 80879ca
Show file tree

Hide file tree

Showing 13 changed files with 38 additions and 38 deletions.
diff --git a/app/protocol/flowcontext/blocks.go b/app/protocol/flowcontext/blocks.go
@@ -20,8 +20,8 @@ func (f *FlowContext) OnNewBlock(block *externalapi.DomainBlock,
 	virtualChangeSet *externalapi.VirtualChangeSet) error {
 
 	hash := consensushashing.BlockHash(block)
-	log.Debugf("OnNewBlock start for block %s", hash)
-	defer log.Debugf("OnNewBlock end for block %s", hash)
+	log.Tracef("OnNewBlock start for block %s", hash)
+	defer log.Tracef("OnNewBlock end for block %s", hash)
 
 	unorphaningResults, err := f.UnorphanBlocks(block)
 	if err != nil {

diff --git a/domain/consensus/processes/consensusstatemanager/add_block_to_virtual.go b/domain/consensus/processes/consensusstatemanager/add_block_to_virtual.go
@@ -79,8 +79,8 @@ func (csm *consensusStateManager) AddBlock(stagingArea *model.StagingArea, block
 func (csm *consensusStateManager) isCandidateToBeNextVirtualSelectedParent(
 	stagingArea *model.StagingArea, blockHash *externalapi.DomainHash) (bool, error) {
 
-	log.Debugf("isCandidateToBeNextVirtualSelectedParent start for block %s", blockHash)
-	defer log.Debugf("isCandidateToBeNextVirtualSelectedParent end for block %s", blockHash)
+	log.Tracef("isCandidateToBeNextVirtualSelectedParent start for block %s", blockHash)
+	defer log.Tracef("isCandidateToBeNextVirtualSelectedParent end for block %s", blockHash)
 
 	if blockHash.Equal(csm.genesisHash) {
 		log.Debugf("Block %s is the genesis block, therefore it is "+
@@ -106,8 +106,8 @@ func (csm *consensusStateManager) isCandidateToBeNextVirtualSelectedParent(
 }
 
 func (csm *consensusStateManager) addTip(stagingArea *model.StagingArea, newTipHash *externalapi.DomainHash) (newTips []*externalapi.DomainHash, err error) {
-	log.Debugf("addTip start for new tip %s", newTipHash)
-	defer log.Debugf("addTip end for new tip %s", newTipHash)
+	log.Tracef("addTip start for new tip %s", newTipHash)
+	defer log.Tracef("addTip end for new tip %s", newTipHash)
 
 	log.Debugf("Calculating the new tips for new tip %s", newTipHash)
 	newTips, err = csm.calculateNewTips(stagingArea, newTipHash)
@@ -124,8 +124,8 @@ func (csm *consensusStateManager) addTip(stagingArea *model.StagingArea, newTipH
 func (csm *consensusStateManager) calculateNewTips(
 	stagingArea *model.StagingArea, newTipHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) {
 
-	log.Debugf("calculateNewTips start for new tip %s", newTipHash)
-	defer log.Debugf("calculateNewTips end for new tip %s", newTipHash)
+	log.Tracef("calculateNewTips start for new tip %s", newTipHash)
+	defer log.Tracef("calculateNewTips end for new tip %s", newTipHash)
 
 	if newTipHash.Equal(csm.genesisHash) {
 		log.Debugf("The new tip is the genesis block, therefore it is the only tip by definition")

diff --git a/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go b/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go
@@ -145,8 +145,8 @@ func (csm *consensusStateManager) applyMergeSetBlocks(stagingArea *model.Staging
 	selectedParentPastUTXODiff externalapi.UTXODiff, daaScore uint64) (
 	externalapi.AcceptanceData, externalapi.MutableUTXODiff, error) {
 
-	log.Debugf("applyMergeSetBlocks start for block %s", blockHash)
-	defer log.Debugf("applyMergeSetBlocks end for block %s", blockHash)
+	log.Tracef("applyMergeSetBlocks start for block %s", blockHash)
+	defer log.Tracef("applyMergeSetBlocks end for block %s", blockHash)
 
 	mergeSetHashes, err := csm.ghostdagManager.GetSortedMergeSet(stagingArea, blockHash)
 	if err != nil {

diff --git a/domain/consensus/processes/consensusstatemanager/check_finality_violation.go b/domain/consensus/processes/consensusstatemanager/check_finality_violation.go
@@ -8,8 +8,8 @@ import (
 func (csm *consensusStateManager) isViolatingFinality(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash,
 ) (isViolatingFinality bool, shouldSendNotification bool, err error) {
 
-	log.Debugf("isViolatingFinality start for block %s", blockHash)
-	defer log.Debugf("isViolatingFinality end for block %s", blockHash)
+	log.Tracef("isViolatingFinality start for block %s", blockHash)
+	defer log.Tracef("isViolatingFinality end for block %s", blockHash)
 
 	if blockHash.Equal(csm.genesisHash) {
 		log.Debugf("Block %s is the genesis block, "+

diff --git a/domain/consensus/processes/consensusstatemanager/import_pruning_utxo_set.go b/domain/consensus/processes/consensusstatemanager/import_pruning_utxo_set.go
@@ -30,8 +30,8 @@ func (csm *consensusStateManager) ImportPruningPointUTXOSet(stagingArea *model.S
 }
 
 func (csm *consensusStateManager) importPruningPointUTXOSet(stagingArea *model.StagingArea, newPruningPoint *externalapi.DomainHash) error {
-	log.Debugf("importPruningPointUTXOSet start")
-	defer log.Debugf("importPruningPointUTXOSet end")
+	log.Tracef("importPruningPointUTXOSet start")
+	defer log.Tracef("importPruningPointUTXOSet end")
 
 	// TODO: We should validate the imported pruning point doesn't violate finality as part of the headers proof.
 

diff --git a/domain/consensus/processes/consensusstatemanager/multisets.go b/domain/consensus/processes/consensusstatemanager/multisets.go
@@ -13,8 +13,8 @@ func (csm *consensusStateManager) calculateMultiset(stagingArea *model.StagingAr
 	blockGHOSTDAGData *externalapi.BlockGHOSTDAGData,
 	daaScore uint64) (model.Multiset, error) {
 
-	log.Debugf("calculateMultiset start for block with selected parent %s", blockGHOSTDAGData.SelectedParent())
-	defer log.Debugf("calculateMultiset end for block with selected parent %s", blockGHOSTDAGData.SelectedParent())
+	log.Tracef("calculateMultiset start for block with selected parent %s", blockGHOSTDAGData.SelectedParent())
+	defer log.Tracef("calculateMultiset end for block with selected parent %s", blockGHOSTDAGData.SelectedParent())
 
 	if blockHash.Equal(csm.genesisHash) {
 		log.Debugf("Selected parent is nil, which could only happen for the genesis. " +

diff --git a/domain/consensus/processes/consensusstatemanager/resolve_block_status.go b/domain/consensus/processes/consensusstatemanager/resolve_block_status.go
@@ -120,8 +120,8 @@ func (csm *consensusStateManager) selectedParentInfo(
 	stagingArea *model.StagingArea, unverifiedBlocks []*externalapi.DomainHash) (
 	*externalapi.DomainHash, externalapi.BlockStatus, externalapi.UTXODiff, error) {
 
-	log.Debugf("findSelectedParentStatus start")
-	defer log.Debugf("findSelectedParentStatus end")
+	log.Tracef("findSelectedParentStatus start")
+	defer log.Tracef("findSelectedParentStatus end")
 
 	lastUnverifiedBlock := unverifiedBlocks[len(unverifiedBlocks)-1]
 	if lastUnverifiedBlock.Equal(csm.genesisHash) {
@@ -156,8 +156,8 @@ func (csm *consensusStateManager) selectedParentInfo(
 func (csm *consensusStateManager) getUnverifiedChainBlocks(stagingArea *model.StagingArea,
 	blockHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) {
 
-	log.Debugf("getUnverifiedChainBlocks start for block %s", blockHash)
-	defer log.Debugf("getUnverifiedChainBlocks end for block %s", blockHash)
+	log.Tracef("getUnverifiedChainBlocks start for block %s", blockHash)
+	defer log.Tracef("getUnverifiedChainBlocks end for block %s", blockHash)
 
 	var unverifiedBlocks []*externalapi.DomainHash
 	currentHash := blockHash

diff --git a/domain/consensus/processes/consensusstatemanager/utxo_diffs.go b/domain/consensus/processes/consensusstatemanager/utxo_diffs.go
@@ -8,8 +8,8 @@ import (
 func (csm *consensusStateManager) stageDiff(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash,
 	utxoDiff externalapi.UTXODiff, utxoDiffChild *externalapi.DomainHash) {
 
-	log.Debugf("stageDiff start for block %s", blockHash)
-	defer log.Debugf("stageDiff end for block %s", blockHash)
+	log.Tracef("stageDiff start for block %s", blockHash)
+	defer log.Tracef("stageDiff end for block %s", blockHash)
 
 	log.Debugf("Staging block %s as the diff child of %s", utxoDiffChild, blockHash)
 	csm.utxoDiffStore.Stage(stagingArea, blockHash, utxoDiff, utxoDiffChild)

diff --git a/domain/consensus/processes/consensusstatemanager/verify_and_build_utxo.go b/domain/consensus/processes/consensusstatemanager/verify_and_build_utxo.go
@@ -19,8 +19,8 @@ func (csm *consensusStateManager) verifyUTXO(stagingArea *model.StagingArea, blo
 	blockHash *externalapi.DomainHash, pastUTXODiff externalapi.UTXODiff, acceptanceData externalapi.AcceptanceData,
 	multiset model.Multiset) error {
 
-	log.Debugf("verifyUTXO start for block %s", blockHash)
-	defer log.Debugf("verifyUTXO end for block %s", blockHash)
+	log.Tracef("verifyUTXO start for block %s", blockHash)
+	defer log.Tracef("verifyUTXO end for block %s", blockHash)
 
 	log.Debugf("Validating UTXO commitment for block %s", blockHash)
 	err := csm.validateUTXOCommitment(block, blockHash, multiset)

diff --git a/domain/consensus/processes/finalitymanager/finality_manager.go b/domain/consensus/processes/finalitymanager/finality_manager.go
@@ -39,8 +39,8 @@ func New(databaseContext model.DBReader,
 }
 
 func (fm *finalityManager) VirtualFinalityPoint(stagingArea *model.StagingArea) (*externalapi.DomainHash, error) {
-	log.Debugf("virtualFinalityPoint start")
-	defer log.Debugf("virtualFinalityPoint end")
+	log.Tracef("virtualFinalityPoint start")
+	defer log.Tracef("virtualFinalityPoint end")
 
 	virtualFinalityPoint, err := fm.calculateFinalityPoint(stagingArea, model.VirtualBlockHash, false)
 	if err != nil {
@@ -52,8 +52,8 @@ func (fm *finalityManager) VirtualFinalityPoint(stagingArea *model.StagingArea)
 }
 
 func (fm *finalityManager) FinalityPoint(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, isBlockWithTrustedData bool) (*externalapi.DomainHash, error) {
-	log.Debugf("FinalityPoint start")
-	defer log.Debugf("FinalityPoint end")
+	log.Tracef("FinalityPoint start")
+	defer log.Tracef("FinalityPoint end")
 	if blockHash.Equal(model.VirtualBlockHash) {
 		return fm.VirtualFinalityPoint(stagingArea)
 	}
@@ -82,8 +82,8 @@ func (fm *finalityManager) calculateAndStageFinalityPoint(
 func (fm *finalityManager) calculateFinalityPoint(stagingArea *model.StagingArea, blockHash *externalapi.DomainHash, isBlockWithTrustedData bool) (
 	*externalapi.DomainHash, error) {
 
-	log.Debugf("calculateFinalityPoint start")
-	defer log.Debugf("calculateFinalityPoint end")
+	log.Tracef("calculateFinalityPoint start")
+	defer log.Tracef("calculateFinalityPoint end")
 
 	if isBlockWithTrustedData {
 		return model.VirtualGenesisBlockHash, nil

diff --git a/domain/consensus/processes/reachabilitymanager/tree.go b/domain/consensus/processes/reachabilitymanager/tree.go
@@ -314,7 +314,7 @@ func (rt *reachabilityManager) addChild(stagingArea *model.StagingArea, node, ch
 		}
 
 		reindexTimeElapsed := time.Since(reindexStartTime)
-		log.Debugf("Reachability reindex triggered for "+
+		log.Tracef("Reachability reindex triggered for "+
 			"block %s. Took %dms.",
 			node, reindexTimeElapsed.Milliseconds())
 
@@ -352,7 +352,7 @@ func (rt *reachabilityManager) updateReindexRoot(stagingArea *model.StagingArea,
 	rc := newReindexContext(rt)
 
 	if !newReindexRoot.Equal(reindexRootAncestor) {
-		log.Debugf("Concentrating the intervals towards the new reindex root")
+		log.Tracef("Concentrating the intervals towards the new reindex root")
 		// Iterate from reindexRootAncestor towards newReindexRoot
 		for {
 			chosenChild, err := rt.FindNextAncestor(stagingArea, selectedTip, reindexRootAncestor)
@@ -375,12 +375,12 @@ func (rt *reachabilityManager) updateReindexRoot(stagingArea *model.StagingArea,
 			reindexRootAncestor = chosenChild
 		}
 	} else {
-		log.Debugf("newReindexRoot is the same as reindexRootAncestor. Skipping concentration...")
+		log.Tracef("newReindexRoot is the same as reindexRootAncestor. Skipping concentration...")
 	}
 
 	// Update reindex root data store
 	rt.stageReindexRoot(stagingArea, newReindexRoot)
-	log.Debugf("Updated the reindex root to %s", newReindexRoot)
+	log.Tracef("Updated the reindex root to %s", newReindexRoot)
 	return nil
 }
 

diff --git a/infrastructure/logger/utils.go b/infrastructure/logger/utils.go
@@ -12,9 +12,9 @@ import (
 // the time duration the function had ran.
 func LogAndMeasureExecutionTime(log *Logger, functionName string) (onEnd func()) {
 	start := time.Now()
-	log.Debugf("%s start", functionName)
+	log.Tracef("%s start", functionName)
 	return func() {
-		log.Debugf("%s end. Took: %s", functionName, time.Since(start))
+		log.Tracef("%s end. Took: %s", functionName, time.Since(start))
 	}
 }
 

diff --git a/util/panics/panics.go b/util/panics/panics.go
@@ -77,8 +77,8 @@ func exit(log *logger.Logger, reason string, currentThreadStackTrace []byte, gor
 func handleSpawnedFunction(log *logger.Logger, stackTrace []byte, spawnedFunctionName string, spawnedFunction func()) {
 	goroutineID := atomic.AddUint64(&goroutineLastID, 1)
 	goroutineName := fmt.Sprintf("%s %d", spawnedFunctionName, goroutineID)
-	utilLog.Debugf("Started goroutine `%s`", goroutineName)
-	defer utilLog.Debugf("Ended goroutine `%s`", goroutineName)
+	utilLog.Tracef("Started goroutine `%s`", goroutineName)
+	defer utilLog.Tracef("Ended goroutine `%s`", goroutineName)
 	defer HandlePanic(log, goroutineName, stackTrace)
 	spawnedFunction()
 }