enhance error logging for pushBlock and validateBlock process

common/blocker/blocker.go

@@ -1,6 +1,7 @@
 package blocker
 
 import (
+	"encoding/json"
 	"fmt"
 
 	"github.com/zoobc/zoobc-core/common/monitoring"
@@ -12,10 +13,13 @@ type (
 	Blocker struct {
 		Type    TypeBlocker
 		Message string
+		Data    interface{}
 	}
 )
 
 var (
+	isDebugMode bool
+
 	DBErr                     TypeBlocker = "DBErr"
 	DBRowNotFound             TypeBlocker = "DBRowNotFound"
 	BlockErr                  TypeBlocker = "BlockErr"
@@ -34,17 +38,34 @@ var (
 	P2PPeerError              TypeBlocker = "P2PPeerError"
 	P2PNetworkConnectionErr   TypeBlocker = "P2PNetworkConnectionErr"
 	SmithingPending           TypeBlocker = "SmithingPending"
+	InvalidBlockTimestamp     TypeBlocker = "InvalidBlockTimestamp"
 	TimeoutExceeded           TypeBlocker = "TimeoutExceeded"
+	PushMainBlockErr          TypeBlocker = "PushMainBlockErr"
+	ValidateMainBlockErr      TypeBlocker = "ValidateMainBlockErr"
+	PushSpineBlockErr         TypeBlocker = "PushSpineBlockErr"
+	ValidateSpineBlockErr     TypeBlocker = "ValidateSpineBlockErr"
 )
 
-func NewBlocker(typeBlocker TypeBlocker, message string) error {
+func SetIsDebugMode(val bool) {
+	isDebugMode = val
+}
+
+func NewBlocker(typeBlocker TypeBlocker, message string, data ...interface{}) error {
 	monitoring.IncrementBlockerMetrics(string(typeBlocker))
-	return Blocker{
+	blocker := Blocker{
 		Type:    typeBlocker,
 		Message: message,
 	}
+	if isDebugMode {
+		blocker.Data = data
+	}
+	return blocker
 }
 
 func (e Blocker) Error() string {
+	if isDebugMode {
+		j, _ := json.Marshal(e.Data)
+		return fmt.Sprintf("%v: %v > %s", e.Type, e.Message, j)
+	}
 	return fmt.Sprintf("%v: %v", e.Type, e.Message)
 }

common/chaintype/util.go

@@ -23,3 +23,9 @@ func GetChainTypes() map[int32]ChainType {
 		spinechain.GetTypeInt(): spinechain,
 	}
 }
+
+// IsSpineChain validates whether a chaintype is a spinechain
+func IsSpineChain(ct ChainType) bool {
+	_, ok := ct.(*SpineChain)
+	return ok
+}

core/blockchainsync/downloadBlockchain.go

@@ -359,7 +359,12 @@ func (bd *BlockchainDownloader) DownloadFromPeer(feederPeer *model.Peer, chainBl
 			err := bd.BlockService.ValidateBlock(block, lastBlock)
 			if err != nil {
 				monitoring.IncrementMainchainDownloadCycleDebugger(bd.ChainType, 69)
-				bd.Logger.Warnf("[download blockchain] failed to verify block %v from peer: %s\nwith previous: %v\n", block.ID, err, lastBlock.ID)
+				blockerUsed := blocker.ValidateMainBlockErr
+				if chaintype.IsSpineChain(bd.ChainType) {
+					blockerUsed = blocker.ValidateSpineBlockErr
+				}
+				bd.Logger.Warnf("[download blockchain] failed to verify block %v from peer: %s\nwith previous: %v\nvalidateBlock fail: %v\n",
+					block.ID, err.Error(), lastBlock.ID, blocker.NewBlocker(blockerUsed, err.Error(), block, lastBlock))
 				blacklistErr := bd.PeerExplorer.PeerBlacklist(feederPeer, err.Error())
 				if blacklistErr != nil {
 					monitoring.IncrementMainchainDownloadCycleDebugger(bd.ChainType, 70)
@@ -377,7 +382,11 @@ func (bd *BlockchainDownloader) DownloadFromPeer(feederPeer *model.Peer, chainBl
 				if blacklistErr != nil {
 					bd.Logger.Errorf("Failed to add blacklist: %v\n", blacklistErr)
 				}
-				bd.Logger.Warn("failed to push block from peer:", err)
+				blockerUsed := blocker.PushMainBlockErr
+				if chaintype.IsSpineChain(bd.ChainType) {
+					blockerUsed = blocker.PushSpineBlockErr
+				}
+				bd.Logger.Warn("[DownloadBlockchain] failed to push block from peer:", blocker.NewBlocker(blockerUsed, err.Error(), block, lastBlock))
 				return &PeerForkInfo{
 					FeederPeer: feederPeer,
 				}, err

core/blockchainsync/processFork.go

@@ -99,8 +99,12 @@ func (fp *ForkingProcessor) ProcessFork(forkBlocks []*model.Block, commonBlock *
 					if blacklistErr != nil {
 						fp.Logger.Errorf("Failed to add blacklist: %v\n", blacklistErr)
 					}
-					fp.Logger.Warnf("[pushing fork block] failed to verify block %v from peer %v: %s\nwith previous: %v\n",
-						block.ID, p2pUtil.GetFullAddressPeer(feederPeer), err, lastBlock.ID)
+					blockerUsed := blocker.ValidateMainBlockErr
+					if chaintype.IsSpineChain(fp.ChainType) {
+						blockerUsed = blocker.ValidateSpineBlockErr
+					}
+					fp.Logger.Warnf("[ProcessFork] failed to verify block %v from peer %v: %s\nwith previous: %v\ndownloadBlockchain validateBlock fail: %v\n",
+						block.ID, p2pUtil.GetFullAddressPeer(feederPeer), err, lastBlock.ID, blocker.NewBlocker(blockerUsed, err.Error(), block, lastBlock))
 					break
 				}
 				err = fp.BlockService.PushBlock(lastBlock, block, false, true)
@@ -110,7 +114,11 @@ func (fp *ForkingProcessor) ProcessFork(forkBlocks []*model.Block, commonBlock *
 					if blacklistErr != nil {
 						fp.Logger.Errorf("Failed to add blacklist: %v\n", blacklistErr)
 					}
-					fp.Logger.Warnf("\n\nPushBlock of fork blocks err %v\n\n", err)
+					blockerUsed := blocker.PushMainBlockErr
+					if chaintype.IsSpineChain(fp.ChainType) {
+						blockerUsed = blocker.PushSpineBlockErr
+					}
+					fp.Logger.Warnf("\n\n[ProcessFork] PushBlock of fork blocks err %v\n\n", blocker.NewBlocker(blockerUsed, err.Error(), block, lastBlock))
 					break
 				}
 
@@ -169,14 +177,24 @@ func (fp *ForkingProcessor) ProcessFork(forkBlocks []*model.Block, commonBlock *
 				if blacklistErr != nil {
 					fp.Logger.Errorf("Failed to add blacklist: %v\n", blacklistErr)
 				}
-				fp.Logger.Warnf("[pushing back own block] failed to verify block %v from peer: %s\n with previous: %v\n", block.ID, err, lastBlock.ID)
+				blockerUsed := blocker.ValidateMainBlockErr
+				if chaintype.IsSpineChain(fp.ChainType) {
+					blockerUsed = blocker.ValidateSpineBlockErr
+				}
+				fp.Logger.Warnf("[pushing back own block] failed to verify block %v from peer: %s\n with previous: %v\nvalidateBlock fail: %v\n",
+					block.ID, err.Error(), lastBlock.ID, blocker.NewBlocker(blockerUsed, err.Error(), block, lastBlock))
 				return err
 			}
 			monitoring.IncrementMainchainDownloadCycleDebugger(fp.ChainType, 112)
 			err = fp.BlockService.PushBlock(lastBlock, block, false, true)
 			monitoring.IncrementMainchainDownloadCycleDebugger(fp.ChainType, 113)
 			if err != nil {
 				monitoring.IncrementMainchainDownloadCycleDebugger(fp.ChainType, 114)
+				blockerUsed := blocker.PushMainBlockErr
+				if chaintype.IsSpineChain(fp.ChainType) {
+					blockerUsed = blocker.PushSpineBlockErr
+				}
+				fp.Logger.Warnf("\n\nPushBlock of fork blocks err %v\n\n", blocker.NewBlocker(blockerUsed, err.Error(), block, lastBlock))
 				return blocker.NewBlocker(blocker.BlockErr, "Popped off block no longer acceptable")
 			}
 		}

core/service/blockMainService.go

@@ -651,14 +651,14 @@ func (bs *BlockService) ScanBlockPool() error {
 		if err == nil {
 			err := bs.ValidateBlock(block, previousBlock)
 			if err != nil {
-				bs.Logger.Warnf("ScanBlockPool:blockValidationFail: %v\n", err)
+				bs.Logger.Warnf("ScanBlockPool:blockValidationFail: %v\n", blocker.NewBlocker(blocker.ValidateMainBlockErr, err.Error(), block, previousBlock))
 				return blocker.NewBlocker(
 					blocker.BlockErr, "ScanBlockPool:ValidateBlockFail",
 				)
 			}
 			err = bs.PushBlock(previousBlock, block, true, true)
 			if err != nil {
-				bs.Logger.Warnf("ScanBlockPool:PushBlockFail: %v\n", err)
+				bs.Logger.Warnf("ScanBlockPool:PushBlockFail: %v\n", blocker.NewBlocker(blocker.PushMainBlockErr, err.Error(), block, previousBlock))
 				return blocker.NewBlocker(
 					blocker.BlockErr, "ScanBlockPool:PushBlockFail",
 				)
@@ -1087,7 +1087,7 @@ func (bs *BlockService) AddGenesis() error {
 	}
 	err = bs.PushBlock(&model.Block{ID: -1, Height: 0}, block, false, true)
 	if err != nil {
-		bs.Logger.Fatal("PushGenesisBlock:fail ", err)
+		bs.Logger.Fatal("PushGenesisBlock:fail ", blocker.NewBlocker(blocker.PushMainBlockErr, err.Error(), block))
 	}
 	return nil
 }
@@ -1498,6 +1498,8 @@ func (bs *BlockService) ProcessCompletedBlock(block *model.Block) error {
 			}
 			err = bs.ValidateBlock(block, previousBlock)
 			if err != nil {
+				bs.Logger.Warnf("ProcessCompletedBlock:blockValidationFail: %v\n",
+					blocker.NewBlocker(blocker.ValidateMainBlockErr, err.Error(), block, previousBlock))
 				return status.Error(codes.InvalidArgument, "InvalidBlock")
 			}
 			lastBlocks, err := bs.PopOffToBlock(previousBlock)
@@ -1507,9 +1509,12 @@ func (bs *BlockService) ProcessCompletedBlock(block *model.Block) error {
 
 			err = bs.PushBlock(previousBlock, block, true, true)
 			if err != nil {
+				bs.Logger.Warn("Push ProcessCompletedBlock:fail ",
+					blocker.NewBlocker(blocker.PushMainBlockErr, err.Error(), block, previousBlock))
 				errPushBlock := bs.PushBlock(previousBlock, lastBlocks[0], false, true)
 				if errPushBlock != nil {
-					bs.Logger.Errorf("pushing back popped off block fail: %v", errPushBlock)
+					bs.Logger.Errorf("ProcessCompletedBlock pushing back popped off block fail: %v",
+						blocker.NewBlocker(blocker.PushMainBlockErr, err.Error(), block, previousBlock))
 					return status.Error(codes.InvalidArgument, "InvalidBlock")
 				}
 				bs.Logger.Info("pushing back popped off block")
@@ -1524,10 +1529,12 @@ func (bs *BlockService) ProcessCompletedBlock(block *model.Block) error {
 	// Validate incoming block
 	err = bs.ValidateBlock(block, lastBlock)
 	if err != nil {
+		bs.Logger.Warnf("ProcessCompletedBlock2:blockValidationFail: %v\n", blocker.NewBlocker(blocker.ValidateMainBlockErr, err.Error(), block, lastBlock))
 		return status.Error(codes.InvalidArgument, "InvalidBlock")
 	}
 	err = bs.PushBlock(lastBlock, block, true, false)
 	if err != nil {
+		bs.Logger.Errorf("ProcessCompletedBlock2 push Block fail: %v", blocker.NewBlocker(blocker.PushMainBlockErr, err.Error(), block, lastBlock))
 		return status.Error(codes.InvalidArgument, err.Error())
 	}
 	return nil

core/service/blockSpineService.go

@@ -653,7 +653,7 @@ func (bs *BlockSpineService) AddGenesis() error {
 	}
 	err = bs.PushBlock(&model.Block{ID: -1, Height: 0}, block, false, true)
 	if err != nil {
-		bs.Logger.Fatal("PushGenesisBlock:fail ", err)
+		bs.Logger.Fatal("PushGenesisBlock:fail ", blocker.NewBlocker(blocker.PushSpineBlockErr, err.Error(), block))
 	}
 	return nil
 }
@@ -716,7 +716,8 @@ func (bs *BlockSpineService) ReceiveBlock(
 				if err != nil {
 					errPushBlock := bs.PushBlock(previousBlock, lastBlocks[0], false, true)
 					if errPushBlock != nil {
-						bs.Logger.Errorf("pushing back popped off block fail: %v", errPushBlock)
+						bs.Logger.Errorf("ReceiveBlock:pushing back popped off block fail: %v",
+							blocker.NewBlocker(blocker.PushSpineBlockErr, err.Error(), block, lastBlock))
 						return status.Error(codes.InvalidArgument, "InvalidBlock")
 					}
 
@@ -727,7 +728,8 @@ func (bs *BlockSpineService) ReceiveBlock(
 				if err != nil {
 					errPushBlock := bs.PushBlock(previousBlock, lastBlocks[0], false, true)
 					if errPushBlock != nil {
-						bs.Logger.Errorf("pushing back popped off block fail: %v", errPushBlock)
+						bs.Logger.Errorf("ReceiveBlock:pushing back popped off block fail: %v",
+							blocker.NewBlocker(blocker.PushSpineBlockErr, err.Error(), block, lastBlock))
 						return status.Error(codes.InvalidArgument, "InvalidBlock")
 					}
 					bs.Logger.Info("pushing back popped off block")
@@ -762,6 +764,7 @@ func (bs *BlockSpineService) ReceiveBlock(
 		}
 		err = bs.PushBlock(lastBlock, block, true, true)
 		if err != nil {
+			bs.Logger.Errorf("receiveBlock pushBlock fail: %v", blocker.NewBlocker(blocker.PushSpineBlockErr, err.Error(), block, lastBlock))
 			return status.Error(codes.InvalidArgument, err.Error())
 		}
 		return nil

core/smith/blockchainProcessor.go

@@ -107,11 +107,21 @@ func (bp *BlockchainProcessor) FakeSmithing(numberOfBlocks int, fromGenesis bool
 		// validate
 		err = bp.BlockService.ValidateBlock(block, previousBlock) // err / !err
 		if err != nil {
+			blockerUsed := blocker.ValidateMainBlockErr
+			if chaintype.IsSpineChain(bp.ChainType) {
+				blockerUsed = blocker.ValidateSpineBlockErr
+			}
+			bp.Logger.Warnf("FakeSmithing: %v\n", blocker.NewBlocker(blockerUsed, err.Error(), block, previousBlock))
 			return err
 		}
 		// if validated push
 		err = bp.BlockService.PushBlock(previousBlock, block, false, true)
 		if err != nil {
+			blockerUsed := blocker.PushMainBlockErr
+			if chaintype.IsSpineChain(bp.ChainType) {
+				blockerUsed = blocker.PushSpineBlockErr
+			}
+			bp.Logger.Errorf("FakeSmithing pushBlock fail: %v", blocker.NewBlocker(blockerUsed, err.Error(), block, previousBlock))
 			return err
 		}
 	}
@@ -152,11 +162,24 @@ func (bp *BlockchainProcessor) StartSmithing() error {
 	// validate
 	err = bp.BlockService.ValidateBlock(block, lastBlock)
 	if err != nil {
+		blockerErr, ok := err.(blocker.Blocker)
+		if ok && blockerErr.Type != blocker.InvalidBlockTimestamp {
+			blockerUsed := blocker.ValidateMainBlockErr
+			if chaintype.IsSpineChain(bp.ChainType) {
+				blockerUsed = blocker.ValidateSpineBlockErr
+			}
+			bp.Logger.Warnf("StartSmithing: %v\n", blocker.NewBlocker(blockerUsed, err.Error(), block, lastBlock))
+		}
 		return err
 	}
 	// if validated push
 	err = bp.BlockService.PushBlock(lastBlock, block, true, false)
 	if err != nil {
+		blockerUsed := blocker.PushMainBlockErr
+		if chaintype.IsSpineChain(bp.ChainType) {
+			blockerUsed = blocker.PushSpineBlockErr
+		}
+		bp.Logger.Errorf("StartSmithing pushBlock fail: %v", blocker.NewBlocker(blockerUsed, err.Error(), block, lastBlock))
 		return err
 	}
 	return nil

core/smith/strategy/blocksmithStrategySpine.go

@@ -191,7 +191,7 @@ func (bss *BlocksmithStrategySpine) IsBlockTimestampValid(
 		elapsedFromLastBlock = blocksmithIndex*ct.GetBlocksmithTimeGap() + ct.GetSmithingPeriod()
 	}
 	if currentBlock.GetTimestamp() < previousBlock.GetTimestamp()+elapsedFromLastBlock {
-		return blocker.NewBlocker(blocker.SmithingErr, "InvalidBlockTimestamp")
+		return blocker.NewBlocker(blocker.InvalidBlockTimestamp, "InvalidBlockTimestamp")
 	}
 	return nil
 }

main.go

@@ -22,6 +22,7 @@ import (
 	"github.com/spf13/viper"
 	"github.com/ugorji/go/codec"
 	"github.com/zoobc/zoobc-core/api"
+	"github.com/zoobc/zoobc-core/common/blocker"
 	"github.com/zoobc/zoobc-core/common/chaintype"
 	"github.com/zoobc/zoobc-core/common/constant"
 	"github.com/zoobc/zoobc-core/common/crypto"
@@ -794,6 +795,7 @@ func main() {
 
 	if isDebugMode {
 		startNodeMonitoring()
+		blocker.SetIsDebugMode(true)
 	}
 
 	mainchainSyncChannel := make(chan bool, 1)

resource/config2.toml

@@ -23,7 +23,7 @@ smithing=true
 proofOfOwnershipReqTimeoutSec = 1
 # Log Levels
 # Available log level: info, warn, error, fatal, panic
-logLevels=["fatal", "error", "panic"]
+logLevels=["fatal", "error", "panic", "warn"]
 
 apiCertFile="./resource/network.crt"
 apiKeyFile="./resource/network.key"

resource/config3.toml

@@ -22,4 +22,4 @@ ownerAccountAddress = "iSJt3H8wFOzlWKsy_UoEWF_OjF6oymHMqthyUMDKSyxb"
 proofOfOwnershipReqTimeoutSec = 1
 # Log Levels
 # Available log level: info, warn, error, fatal, panic
-logLevels=["fatal", "error", "panic"]
+logLevels=["fatal", "error", "panic", "warn"]