Refactor/fix state sync logs (#515)

## Description

Improves logs for the state sync submodule.

## Issue

Fixes #514 

## Type of change

Please mark the relevant option(s):

- [ ] New feature, functionality or library
- [ ] Bug fix
- [X] Code health or cleanup
- [ ] Major breaking change
- [ ] Documentation
- [ ] Other <!-- add details here if it a different type of change -->

## List of changes

- Add constant state sync message types to the consensus module types
- Update logs and error messages of the state sync
- Delete unnecessary server mode enabling op in app/pocket/main.go


## Testing

- [X] `make develop_test`
- [X]
[LocalNet](https://github.com/pokt-network/pocket/blob/main/docs/development/README.md)
w/ all of the steps outlined in the `README`

## Required Checklist

- [X] I have performed a self-review of my own code
- [X] I have commented my code, particularly in hard-to-understand areas
- [X] I have tested my changes using the available tooling
- [X] I have updated the corresponding CHANGELOG

### If Applicable Checklist

- [ ] I have updated the corresponding README(s); local and/or global
- [ ] I have added tests that prove my fix is effective or that my
feature works
- [ ] I have added, or updated,
[mermaid.js](https://mermaid-js.github.io) diagrams in the corresponding
README(s)
- [ ] I have added, or updated, documentation and
[mermaid.js](https://mermaid-js.github.io) diagrams in `shared/docs/*`
if I updated `shared/*`README(s)

---------

Co-authored-by: Daniel Olshansky <[email protected]>

Author: gokutheengineer

app/pocket/doc/CHANGELOG.md

@@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+## [0.0.0.5] - 2023-02-17
+
+- Removed unnecessary server mode enabling call via `EnableServerMode()` function
+
 ## [0.0.0.4] - 2023-02-07
 
 - Added GITHUB_WIKI tags where it was missing

app/pocket/main.go

@@ -31,7 +31,6 @@ func main() {
 	if err != nil {
 		logger.Global.Fatal().Err(err).Msg("Failed to create pocket node")
 	}
-	pocketNode.GetBus().GetConsensusModule().EnableServerMode()
 
 	if err = pocketNode.Start(); err != nil {
 		logger.Global.Fatal().Err(err).Msg("Failed to start pocket node")

consensus/debugging.go

@@ -124,9 +124,12 @@ func (m *consensusModule) sendGetBlockStateSyncMessage(_ *messaging.DebugMessage
 	}
 
 	for _, val := range validators {
+		if m.GetNodeAddress() == val.GetAddress() {
+			continue
+		}
 		valAddress := cryptoPocket.AddressFromString(val.GetAddress())
 		if err := m.stateSync.SendStateSyncMessage(stateSyncGetBlockMessage, valAddress, requestHeight); err != nil {
-			m.logger.Debug().Msgf(typesCons.SendingStateSyncMessage(valAddress, requestHeight), err)
+			m.logger.Error().Err(err).Str("proto_type", "GetBlockRequest").Msg("failed to send StateSyncMessage")
 		}
 	}
 }
@@ -151,9 +154,12 @@ func (m *consensusModule) sendGetMetadataStateSyncMessage(_ *messaging.DebugMess
 	}
 
 	for _, val := range validators {
+		if m.GetNodeAddress() != val.GetAddress() {
+			continue
+		}
 		valAddress := cryptoPocket.AddressFromString(val.GetAddress())
 		if err := m.stateSync.SendStateSyncMessage(stateSyncMetaDataReqMessage, valAddress, requestHeight); err != nil {
-			m.logger.Debug().Msgf(typesCons.SendingStateSyncMessage(valAddress, requestHeight), err)
+			m.logger.Error().Err(err).Str("proto_type", "GetMetaDataRequest").Msg("failed to send StateSyncMessage")
 		}
 	}
 

consensus/doc/CHANGELOG.md

@@ -7,6 +7,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+## [0.0.0.30] - 2023-02-17
+
+- Updated log messages in the state sync submodule with consistent style and add height information
+- Added state sync message types to the types package
+
 ## [0.0.0.29] - 2023-02-17
 
 - Modules embed `base_modules.IntegratableModule` and `base_modules.InterruptableModule` for DRYness

consensus/state_sync/helpers.go

@@ -6,12 +6,19 @@ import (
 	"google.golang.org/protobuf/types/known/anypb"
 )
 
-func (m *stateSync) SendStateSyncMessage(stateSyncMsg *typesCons.StateSyncMessage, peerId cryptoPocket.Address, blockHeight uint64) error {
+func (m *stateSync) SendStateSyncMessage(stateSyncMsg *typesCons.StateSyncMessage, peerId cryptoPocket.Address, height uint64) error {
 	anyMsg, err := anypb.New(stateSyncMsg)
 	if err != nil {
 		return err
 	}
-	m.logger.Info().Uint64("height", blockHeight).Msg(typesCons.SendingStateSyncMessage(peerId, blockHeight))
+
+	fields := map[string]any{
+		"height":     height,
+		"peerId":     peerId,
+		"proto_type": getMessageType(stateSyncMsg),
+	}
+
+	m.logger.Info().Fields(fields).Msg("Sending StateSync Message")
 	return m.sendToPeer(anyMsg, peerId)
 }
 
@@ -23,3 +30,18 @@ func (m *stateSync) sendToPeer(msg *anypb.Any, peerId cryptoPocket.Address) erro
 	}
 	return nil
 }
+
+func getMessageType(msg *typesCons.StateSyncMessage) string {
+	switch msg.Message.(type) {
+	case *typesCons.StateSyncMessage_MetadataReq:
+		return "MetadataRequest"
+	case *typesCons.StateSyncMessage_MetadataRes:
+		return "MetadataResponse"
+	case *typesCons.StateSyncMessage_GetBlockReq:
+		return "GetBlockRequest"
+	case *typesCons.StateSyncMessage_GetBlockRes:
+		return "GetBlockResponse"
+	default:
+		return "Unknown"
+	}
+}

consensus/state_sync/module.go

@@ -36,7 +36,7 @@ type StateSyncModule interface {
 	IsServerModEnabled() bool
 	EnableServerMode()
 
-	SendStateSyncMessage(*typesCons.StateSyncMessage, cryptoPocket.Address, uint64) error
+	SendStateSyncMessage(msg *typesCons.StateSyncMessage, nodeAddress cryptoPocket.Address, height uint64) error
 }
 
 var (
@@ -71,6 +71,7 @@ func (*stateSync) Create(bus modules.Bus, options ...modules.ModuleOption) (modu
 	bus.RegisterModule(m)
 
 	// when node is starting, it is in sync mode, as it might need to bootstrap to the latest state
+	// TODO: change this to to reflect the state in the fsm once merged
 	m.currentMode = Sync
 	m.serverMode = false
 
@@ -118,13 +119,36 @@ func (m *stateSync) EnableServerMode() {
 // TODO(#352): Implement this function
 // Placeholder function
 func (m *stateSync) HandleGetBlockResponse(blockRes *typesCons.GetBlockResponse) error {
-	m.logger.Debug().Msgf("Received get block response: %s", blockRes.Block.String())
+	consensusMod := m.GetBus().GetConsensusModule()
+	serverNodePeerId := consensusMod.GetNodeAddress()
+	clientPeerId := blockRes.PeerAddress
+
+	fields := map[string]any{
+		"currentHeight": blockRes.Block.BlockHeader.Height,
+		"sender":        serverNodePeerId,
+		"receiver":      clientPeerId,
+	}
+
+	m.logger.Info().Fields(fields).Msgf("Received StateSync GetBlockResponse: %s", blockRes)
+
 	return nil
 }
 
 // TODO(#352): Implement the business to handle these correctly
 // Placeholder function
 func (m *stateSync) HandleStateSyncMetadataResponse(metaDataRes *typesCons.StateSyncMetadataResponse) error {
-	m.logger.Debug().Msgf("Received get metadata response: %s", metaDataRes.String())
+	consensusMod := m.GetBus().GetConsensusModule()
+	serverNodePeerId := consensusMod.GetNodeAddress()
+	clientPeerId := metaDataRes.PeerAddress
+	currentHeight := consensusMod.CurrentHeight()
+
+	fields := map[string]any{
+		"currentHeight": currentHeight,
+		"sender":        serverNodePeerId,
+		"receiver":      clientPeerId,
+	}
+
+	m.logger.Info().Fields(fields).Msgf("Received StateSync MetadataResponse: %s", metaDataRes)
+
 	return nil
 }

consensus/state_sync/server.go

@@ -22,13 +22,20 @@ type StateSyncServerModule interface {
 
 func (m *stateSync) HandleStateSyncMetadataRequest(metadataReq *typesCons.StateSyncMetadataRequest) error {
 	consensusMod := m.GetBus().GetConsensusModule()
-	serverNodePeerId := m.GetBus().GetConsensusModule().GetNodeAddress()
-
+	serverNodePeerAddress := consensusMod.GetNodeAddress()
 	clientPeerAddress := metadataReq.PeerAddress
-	m.logger.Info().Msgf("%s received state sync metadata request from: %s", serverNodePeerId, clientPeerAddress)
+	// current height is the height of the block that is being processed, so we need to subtract 1 for the last finalized block
+	lastPersistedBlockHeight := consensusMod.CurrentHeight() - 1
+
+	fields := map[string]any{
+		"height":   lastPersistedBlockHeight,
+		"sender":   serverNodePeerAddress,
+		"receiver": clientPeerAddress,
+	}
+
+	m.logger.Info().Fields(fields).Msgf("Received StateSync Metadata %s", metadataReq)
 
-	// last finalized block
-	persistenceContext, err := m.GetBus().GetPersistenceModule().NewReadContext(int64(consensusMod.CurrentHeight()) - 1)
+	persistenceContext, err := m.GetBus().GetPersistenceModule().NewReadContext(int64(lastPersistedBlockHeight))
 	if err != nil {
 		return nil
 	}
@@ -47,7 +54,7 @@ func (m *stateSync) HandleStateSyncMetadataRequest(metadataReq *typesCons.StateS
 	stateSyncMessage := typesCons.StateSyncMessage{
 		Message: &typesCons.StateSyncMessage_MetadataRes{
 			MetadataRes: &typesCons.StateSyncMetadataResponse{
-				PeerAddress: serverNodePeerId,
+				PeerAddress: serverNodePeerAddress,
 				MinHeight:   minHeight,
 				MaxHeight:   uint64(maxHeight),
 			},
@@ -60,14 +67,20 @@ func (m *stateSync) HandleStateSyncMetadataRequest(metadataReq *typesCons.StateS
 func (m *stateSync) HandleGetBlockRequest(blockReq *typesCons.GetBlockRequest) error {
 	consensusMod := m.GetBus().GetConsensusModule()
 	serverNodePeerAddress := consensusMod.GetNodeAddress()
-
 	clientPeerAddress := blockReq.PeerAddress
-	m.logger.Info().Msgf("%s received state sync Get Block Req from: %s", serverNodePeerAddress, clientPeerAddress)
+	// current height is the height of the block that is being processed, so we need to subtract 1 for the last finalized block
+	lastPersistedBlockHeight := consensusMod.CurrentHeight() - 1
+
+	fields := map[string]any{
+		"height":   lastPersistedBlockHeight,
+		"sender":   serverNodePeerAddress,
+		"receiver": clientPeerAddress,
+	}
 
-	currentHeight := m.GetBus().GetConsensusModule().CurrentHeight()
+	m.logger.Info().Fields(fields).Msgf("Received StateSync GetBlockRequest: %s", blockReq)
 
-	if currentHeight < blockReq.Height {
-		return fmt.Errorf("requested block height: %d is higher than node's block height: %d", blockReq.Height, consensusMod.CurrentHeight())
+	if lastPersistedBlockHeight < blockReq.Height {
+		return fmt.Errorf("requested block height: %d is higher than current persisted block height: %d", blockReq.Height, lastPersistedBlockHeight)
 	}
 
 	// get block from the persistence module

consensus/types/errors.go consensus/types/messages.go

@@ -9,7 +9,6 @@ import (
 
 	"github.com/pokt-network/pocket/logger"
 	"github.com/pokt-network/pocket/shared/codec"
-	cryptoPocket "github.com/pokt-network/pocket/shared/crypto"
 	"google.golang.org/protobuf/proto"
 )
 
@@ -83,10 +82,6 @@ func SendingMessage(msg *HotstuffMessage, nodeId NodeId) string {
 	return fmt.Sprintf("✉️ Sending message ✉️ to %d at (height, step, round) (%d, %d, %d)", nodeId, msg.Height, msg.Step, msg.Round)
 }
 
-func SendingStateSyncMessage(nodeId cryptoPocket.Address, height uint64) string {
-	return fmt.Sprintf("🔄 Sending State sync message ✉️ to node %s at height: (%d)  🔄", nodeId, height)
-}
-
 func BroadcastingMessage(msg *HotstuffMessage) string {
 	return fmt.Sprintf("📣 Broadcasting message 📣 (height, step, round): (%d, %d, %d)", msg.GetHeight(), msg.GetStep(), msg.GetRound())
 }