fix: standardize mini-protocol debug logging (#741)

Signed-off-by: Chris Gianelloni <wolf31o2@blinklabs.io>
blinklabs-io · Oct 5, 2024 · 4e361c5 · 4e361c5
1 parent 59c7df4
commit 4e361c5
Show file tree

Hide file tree

Showing 18 changed files with 110 additions and 101 deletions.
diff --git a/protocol/blockfetch/client.go b/protocol/blockfetch/client.go
@@ -82,7 +82,7 @@ func NewClient(protoOptions protocol.ProtocolOptions, cfg *Config) *Client {
 func (c *Client) Start() {
 	c.onceStart.Do(func() {
 		c.Protocol.Logger().
-			Debug(fmt.Sprintf("%s: starting protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
+			Debug(fmt.Sprintf("%s: starting client protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
 		c.Protocol.Start()
 		// Start goroutine to cleanup resources on protocol shutdown
 		go func() {
@@ -97,7 +97,7 @@ func (c *Client) Stop() error {
 	var err error
 	c.onceStop.Do(func() {
 		c.Protocol.Logger().
-			Debug(fmt.Sprintf("%s: stopping protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
+			Debug(fmt.Sprintf("%s: stopping client protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
 		msg := NewMsgClientDone()
 		err = c.SendMessage(msg)
 	})

diff --git a/protocol/blockfetch/server.go b/protocol/blockfetch/server.go
@@ -61,21 +61,21 @@ func (s *Server) initProtocol() {
 
 func (s *Server) NoBlocks() error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("server called %s NoBlocks()", ProtocolName))
+		Debug(fmt.Sprintf("%s: server %+v called NoBlocks()", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	msg := NewMsgNoBlocks()
 	return s.SendMessage(msg)
 }
 
 func (s *Server) StartBatch() error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("server called %s StartBatch()", ProtocolName))
+		Debug(fmt.Sprintf("%s: server %+v called StartBatch()", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	msg := NewMsgStartBatch()
 	return s.SendMessage(msg)
 }
 
 func (s *Server) Block(blockType uint, blockData []byte) error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("server called %s Block(blockType: %+v, blockData: %x)", ProtocolName, blockType, blockData))
+		Debug(fmt.Sprintf("%s: server %+v called Block(blockType: %+v, blockData: %x)", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr, blockType, blockData))
 	wrappedBlock := WrappedBlock{
 		Type:     blockType,
 		RawBlock: blockData,
@@ -90,14 +90,12 @@ func (s *Server) Block(blockType uint, blockData []byte) error {
 
 func (s *Server) BatchDone() error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("server called %s BatchDone()", ProtocolName))
+		Debug(fmt.Sprintf("%s: server %+v called BatchDone()", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	msg := NewMsgBatchDone()
 	return s.SendMessage(msg)
 }
 
 func (s *Server) messageHandler(msg protocol.Message) error {
-	s.Protocol.Logger().
-		Debug(fmt.Sprintf("handling server message for %s", ProtocolName))
 	var err error
 	switch msg.Type() {
 	case MessageTypeRequestRange:
@@ -116,7 +114,7 @@ func (s *Server) messageHandler(msg protocol.Message) error {
 
 func (s *Server) handleRequestRange(msg protocol.Message) error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("handling server request range for %s", ProtocolName))
+		Debug(fmt.Sprintf("%s: server request range for %+v", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	if s.config == nil || s.config.RequestRangeFunc == nil {
 		return fmt.Errorf(
 			"received block-fetch RequestRange message but no callback function is defined",
@@ -132,7 +130,7 @@ func (s *Server) handleRequestRange(msg protocol.Message) error {
 
 func (s *Server) handleClientDone() error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("handling server client done for %s", ProtocolName))
+		Debug(fmt.Sprintf("%s: server client done for %+v", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	// Restart protocol
 	s.Protocol.Stop()
 	s.initProtocol()

diff --git a/protocol/chainsync/client.go b/protocol/chainsync/client.go
@@ -117,7 +117,7 @@ func NewClient(
 func (c *Client) Start() {
 	c.onceStart.Do(func() {
 		c.Protocol.Logger().
-			Debug(fmt.Sprintf("%s: starting protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
+			Debug(fmt.Sprintf("%s: starting client protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
 		c.Protocol.Start()
 		// Start goroutine to cleanup resources on protocol shutdown
 		go func() {
@@ -132,7 +132,7 @@ func (c *Client) Stop() error {
 	var err error
 	c.onceStop.Do(func() {
 		c.Protocol.Logger().
-			Debug(fmt.Sprintf("%s: stopping protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
+			Debug(fmt.Sprintf("%s: stopping client protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
 		c.busyMutex.Lock()
 		defer c.busyMutex.Unlock()
 		msg := NewMsgDone()

diff --git a/protocol/chainsync/server.go b/protocol/chainsync/server.go
@@ -79,21 +79,21 @@ func (s *Server) initProtocol() {
 
 func (s *Server) RollBackward(point common.Point, tip Tip) error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("server called %s RollBackward(point: %+v, tip: %+v)", ProtocolName, point, tip))
+		Debug(fmt.Sprintf("%s: server %+v called RollBackward(point: {Slot: %d, Hash: %x}, tip: {Point: %+v, BlockNumber: %d})", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr, point.Slot, point.Hash, tip.Point, tip.BlockNumber))
 	msg := NewMsgRollBackward(point, tip)
 	return s.SendMessage(msg)
 }
 
 func (s *Server) AwaitReply() error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("server called %s AwaitReply()", ProtocolName))
+		Debug(fmt.Sprintf("%s: server %+v called AwaitReply()", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	msg := NewMsgAwaitReply()
 	return s.SendMessage(msg)
 }
 
 func (s *Server) RollForward(blockType uint, blockData []byte, tip Tip) error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("server called %s Rollforward(blockType: %+v, blockData: %x, tip: %+v)", ProtocolName, blockType, blockData, tip))
+		Debug(fmt.Sprintf("%s: server %+v called RollForward(blockType: %+v, blockData: %x, tip: {Point: {Slot: %d, Hash: %x}, BlockNumber: %d})", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr, blockType, blockData, tip.Point.Slot, tip.Point.Hash, tip.BlockNumber))
 	if s.Mode() == protocol.ProtocolModeNodeToNode {
 		eraId := ledger.BlockToBlockHeaderTypeMap[blockType]
 		msg := NewMsgRollForwardNtN(
@@ -114,8 +114,6 @@ func (s *Server) RollForward(blockType uint, blockData []byte, tip Tip) error {
 }
 
 func (s *Server) messageHandler(msg protocol.Message) error {
-	s.Protocol.Logger().
-		Debug(fmt.Sprintf("handling server message for %s", ProtocolName))
 	var err error
 	switch msg.Type() {
 	case MessageTypeRequestNext:
@@ -137,8 +135,8 @@ func (s *Server) messageHandler(msg protocol.Message) error {
 func (s *Server) handleRequestNext() error {
 	// TODO: figure out why this one log message causes a panic (and only this one)
 	//   during tests
-	// s.Protocol.Logger().
-	// 	Debug(fmt.Sprintf("handling server request next for %s", ProtocolName))
+	//s.Protocol.Logger().
+	//	Debug(fmt.Sprintf("%s: server request next for %+v", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	if s.config == nil || s.config.RequestNextFunc == nil {
 		return fmt.Errorf(
 			"received chain-sync RequestNext message but no callback function is defined",
@@ -149,7 +147,7 @@ func (s *Server) handleRequestNext() error {
 
 func (s *Server) handleFindIntersect(msg protocol.Message) error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("handling server find intersect for %s", ProtocolName))
+		Debug(fmt.Sprintf("%s: server find intersect for %+v", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	if s.config == nil || s.config.FindIntersectFunc == nil {
 		return fmt.Errorf(
 			"received chain-sync FindIntersect message but no callback function is defined",
@@ -179,7 +177,7 @@ func (s *Server) handleFindIntersect(msg protocol.Message) error {
 
 func (s *Server) handleDone() error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("handling server done for %s", ProtocolName))
+		Debug(fmt.Sprintf("%s: server done for %+v", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	// Restart protocol
 	s.Protocol.Stop()
 	s.initProtocol()

diff --git a/protocol/handshake/client.go b/protocol/handshake/client.go
@@ -70,7 +70,7 @@ func NewClient(protoOptions protocol.ProtocolOptions, cfg *Config) *Client {
 func (c *Client) Start() {
 	c.onceStart.Do(func() {
 		c.Protocol.Logger().
-			Debug(fmt.Sprintf("%s: starting protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
+			Debug(fmt.Sprintf("%s: starting client protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
 		c.Protocol.Start()
 		// Send our ProposeVersions message
 		msg := NewMsgProposeVersions(c.config.ProtocolVersionMap)

diff --git a/protocol/handshake/server.go b/protocol/handshake/server.go
@@ -61,8 +61,6 @@ func NewServer(protoOptions protocol.ProtocolOptions, cfg *Config) *Server {
 }
 
 func (s *Server) handleMessage(msg protocol.Message) error {
-	s.Protocol.Logger().
-		Debug(fmt.Sprintf("handling server message for %s", ProtocolName))
 	var err error
 	switch msg.Type() {
 	case MessageTypeProposeVersions:
@@ -79,7 +77,7 @@ func (s *Server) handleMessage(msg protocol.Message) error {
 
 func (s *Server) handleProposeVersions(msg protocol.Message) error {
 	s.Protocol.Logger().
-		Debug(fmt.Sprintf("handling server propose versions for %s", ProtocolName))
+		Debug(fmt.Sprintf("%s: server propose versions for %+v", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	if s.config.FinishedFunc == nil {
 		return fmt.Errorf(
 			"received handshake ProposeVersions message but no callback function is defined",

diff --git a/protocol/keepalive/client.go b/protocol/keepalive/client.go
@@ -70,7 +70,7 @@ func NewClient(protoOptions protocol.ProtocolOptions, cfg *Config) *Client {
 func (c *Client) Start() {
 	c.onceStart.Do(func() {
 		c.Protocol.Logger().
-			Debug(fmt.Sprintf("%s: starting protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
+			Debug(fmt.Sprintf("%s: starting client protocol for connection %+v", ProtocolName, c.callbackContext.ConnectionId.RemoteAddr))
 		c.Protocol.Start()
 		// Start goroutine to cleanup resources on protocol shutdown
 		go func() {

diff --git a/protocol/keepalive/server.go b/protocol/keepalive/server.go
@@ -38,6 +38,7 @@ func NewServer(protoOptions protocol.ProtocolOptions, cfg *Config) *Server {
 		Name:                ProtocolName,
 		ProtocolId:          ProtocolId,
 		Muxer:               protoOptions.Muxer,
+		Logger:              protoOptions.Logger,
 		ErrorChan:           protoOptions.ErrorChan,
 		Mode:                protoOptions.Mode,
 		Role:                protocol.ProtocolRoleServer,
@@ -68,6 +69,8 @@ func (s *Server) messageHandler(msg protocol.Message) error {
 }
 
 func (s *Server) handleKeepAlive(msgGeneric protocol.Message) error {
+	s.Protocol.Logger().
+		Debug(fmt.Sprintf("%s: server keep alive for %+v", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	msg := msgGeneric.(*MsgKeepAlive)
 	if s.config != nil && s.config.KeepAliveFunc != nil {
 		// Call the user callback function
@@ -80,6 +83,8 @@ func (s *Server) handleKeepAlive(msgGeneric protocol.Message) error {
 }
 
 func (s *Server) handleDone() error {
+	s.Protocol.Logger().
+		Debug(fmt.Sprintf("%s: server done for %+v", ProtocolName, s.callbackContext.ConnectionId.RemoteAddr))
 	if s.config != nil && s.config.DoneFunc != nil {
 		// Call the user callback function
 		return s.config.DoneFunc(s.callbackContext)