chore: better logging by showing short string for peer-id (#696)

Co-authored-by: Kay <[email protected]>

network/gossip.go

@@ -100,7 +100,8 @@ func (g *gossipService) onReceiveMessage(m *lp2pps.Message) {
 		return
 	}
 
-	g.logger.Debug("receiving new gossip message", "from", m.GetFrom(), "received from", m.ReceivedFrom)
+	g.logger.Debug("receiving new gossip message",
+		"source", m.GetFrom().ShortString(), "from", m.ReceivedFrom.ShortString())
 	event := &GossipMessage{
 		Source: m.GetFrom(),
 		From:   m.ReceivedFrom,

network/notifee.go

@@ -39,20 +39,20 @@ func (n *NotifeeService) Connected(lp2pn lp2pnetwork.Network, conn lp2pnetwork.C
 
 			protocols, _ := lp2pn.Peerstore().SupportsProtocols(peerID, n.protocolID)
 			if len(protocols) > 0 {
-				n.logger.Info("connected to peer", "pid", peerID)
+				n.logger.Info("connected to peer", "pid", peerID.ShortString())
 				n.eventChannel <- &ConnectEvent{PeerID: peerID}
 
 				return
 			}
 		}
 
-		n.logger.Info("this node doesn't support stream protocol", "pid", peerID)
+		n.logger.Info("this node doesn't support stream protocol", "pid", peerID.ShortString())
 	}()
 }
 
 func (n *NotifeeService) Disconnected(_ lp2pnetwork.Network, conn lp2pnetwork.Conn) {
 	peerID := conn.RemotePeer()
-	n.logger.Info("disconnected from peer", "pid", peerID)
+	n.logger.Info("disconnected from peer", "pid", peerID.ShortString())
 	n.eventChannel <- &DisconnectEvent{PeerID: peerID}
 }
 

network/stream.go

@@ -47,7 +47,7 @@ func (s *streamService) Stop() {
 func (s *streamService) handleStream(stream lp2pnetwork.Stream) {
 	from := stream.Conn().RemotePeer()
 
-	s.logger.Debug("receiving stream", "from", from)
+	s.logger.Debug("receiving stream", "from", from.ShortString())
 	event := &StreamMessage{
 		Source: from,
 		Reader: stream,
@@ -60,7 +60,7 @@ func (s *streamService) handleStream(stream lp2pnetwork.Stream) {
 // If a direct connection can't be established, it attempts to connect via a relay node.
 // Returns an error if the sending process fails.
 func (s *streamService) SendRequest(msg []byte, pid lp2peer.ID) error {
-	s.logger.Trace("sending stream", "to", pid)
+	s.logger.Trace("sending stream", "to", pid.ShortString())
 	_, err := s.host.Peerstore().SupportsProtocols(pid, s.protocolID)
 	if err != nil {
 		return LibP2PError{Err: err}
@@ -70,7 +70,7 @@ func (s *streamService) SendRequest(msg []byte, pid lp2peer.ID) error {
 	stream, err := s.host.NewStream(
 		lp2pnetwork.WithNoDial(s.ctx, "should already have connection"), pid, s.protocolID)
 	if err != nil {
-		s.logger.Debug("unable to open direct stream", "pid", pid, "error", err)
+		s.logger.Debug("unable to open direct stream", "pid", pid.ShortString(), "error", err)
 		if len(s.relayAddrs) == 0 {
 			return err
 		}
@@ -100,17 +100,17 @@ func (s *streamService) SendRequest(msg []byte, pid lp2peer.ID) error {
 
 		if err := s.host.Connect(s.ctx, unreachableRelayInfo); err != nil {
 			// There is no relay connection to peer as well
-			s.logger.Warn("unable to connect to peer using relay", "pid", pid, "error", err)
+			s.logger.Warn("unable to connect to peer using relay", "pid", pid.ShortString(), "error", err)
 			return LibP2PError{Err: err}
 		}
-		s.logger.Debug("connected to peer using relay", "pid", pid)
+		s.logger.Debug("connected to peer using relay", "pid", pid.ShortString())
 
 		// Try to open a new stream to the target peer using the relay connection.
 		// The connection is marked as transient.
 		stream, err = s.host.NewStream(
 			lp2pnetwork.WithUseTransient(s.ctx, string(s.protocolID)), pid, s.protocolID)
 		if err != nil {
-			s.logger.Warn("unable to open relay stream", "pid", pid, "error", err)
+			s.logger.Warn("unable to open relay stream", "pid", pid.ShortString(), "error", err)
 			return LibP2PError{Err: err}
 		}
 	}

sync/firewall/firewall.go

@@ -40,7 +40,7 @@ func (f *Firewall) OpenGossipBundle(data []byte, source peer.ID, from peer.ID) *
 	if from != source {
 		f.peerSet.UpdateLastReceived(from)
 		if f.isPeerBanned(from) {
-			f.logger.Warn("firewall: from peer banned", "from", from)
+			f.logger.Warn("firewall: from peer banned", "from", from.ShortString())
 			f.closeConnection(from)
 			return nil
 		}

sync/handler_blocks_request.go

@@ -95,9 +95,11 @@ func (handler *blocksRequestHandler) PrepareBundle(m message.Message) *bundle.Bu
 
 func (handler *blocksRequestHandler) respond(msg *message.BlocksResponseMessage, to peer.ID) error {
 	if msg.ResponseCode == message.ResponseCodeRejected {
-		handler.logger.Warn("rejecting block request message", "message", msg, "to", to, "reason", msg.Reason)
+		handler.logger.Warn("rejecting block request message", "message", msg,
+			"to", to.ShortString(), "reason", msg.Reason)
 	} else {
-		handler.logger.Info("responding block request message", "message", msg, "to", to)
+		handler.logger.Info("responding block request message", "message", msg,
+			"to", to.ShortString())
 	}
 
 	return handler.sendTo(msg, to)

sync/handler_blocks_response.go

@@ -22,7 +22,7 @@ func (handler *blocksResponseHandler) ParseMessage(m message.Message, initiator
 	handler.logger.Trace("parsing BlocksResponse message", "message", msg)
 
 	if msg.IsRequestRejected() {
-		handler.logger.Warn("blocks request is rejected", "pid", initiator, "reason", msg.Reason)
+		handler.logger.Warn("blocks request is rejected", "pid", initiator.ShortString(), "reason", msg.Reason)
 	} else {
 		height := msg.From
 		for _, data := range msg.CommittedBlocksData {
@@ -63,7 +63,7 @@ func (handler *blocksResponseHandler) updateSession(sessionID int, pid peer.ID,
 
 	if s.PeerID() != pid {
 		// TODO: test me
-		handler.logger.Warn("unknown peer", "session-id", sessionID, "pid", pid)
+		handler.logger.Warn("unknown peer", "session-id", sessionID, "pid", pid.ShortString())
 		return
 	}
 

sync/handler_hello.go

@@ -39,7 +39,7 @@ func (handler *helloHandler) ParseMessage(m message.Message, initiator peer.ID)
 	}
 
 	handler.logger.Debug("updating peer info",
-		"pid", initiator,
+		"pid", initiator.ShortString(),
 		"moniker", msg.Moniker,
 		"services", msg.Services)
 
@@ -65,9 +65,11 @@ func (handler *helloHandler) acknowledge(msg *message.HelloAckMessage, to peer.I
 	if msg.ResponseCode == message.ResponseCodeRejected {
 		handler.peerSet.UpdateStatus(to, peerset.StatusCodeBanned)
 
-		handler.logger.Warn("rejecting hello message", "message", msg, "to", to, "reason", msg.Reason)
+		handler.logger.Warn("rejecting hello message", "message", msg,
+			"to", to.ShortString(), "reason", msg.Reason)
 	} else {
-		handler.logger.Info("acknowledging hello message", "message", msg, "to", to)
+		handler.logger.Info("acknowledging hello message", "message", msg,
+			"to", to.ShortString())
 	}
 
 	return handler.sendTo(msg, to)

sync/handler_hello_ack.go

@@ -23,13 +23,15 @@ func (handler *helloAckHandler) ParseMessage(m message.Message, initiator peer.I
 	handler.logger.Trace("parsing HelloAck message", "message", msg)
 
 	if msg.ResponseCode != message.ResponseCodeOK {
-		handler.logger.Warn("hello message rejected", "from", initiator, "reason", msg.Reason)
+		handler.logger.Warn("hello message rejected",
+			"from", initiator.ShortString(), "reason", msg.Reason)
 
 		handler.network.CloseConnection(initiator)
 		return nil
 	}
 	handler.peerSet.UpdateStatus(initiator, peerset.StatusCodeKnown)
-	handler.logger.Debug("hello message acknowledged", "from", initiator)
+	handler.logger.Debug("hello message acknowledged",
+		"from", initiator.ShortString())
 
 	return nil
 }

sync/sync.go

@@ -143,7 +143,7 @@ func (sync *synchronizer) sayHello(to peer.ID) error {
 
 	sync.peerSet.UpdateStatus(to, peerset.StatusCodeConnected)
 
-	sync.logger.Info("sending Hello message", "to", to)
+	sync.logger.Info("sending Hello message", "to", to.ShortString())
 	return sync.sendTo(msg, to)
 }
 
@@ -173,7 +173,8 @@ func (sync *synchronizer) receiveLoop() {
 				bdl := sync.firewall.OpenGossipBundle(ge.Data, ge.Source, ge.From)
 				err := sync.processIncomingBundle(bdl)
 				if err != nil {
-					sync.logger.Warn("error on parsing a Gossip bundle", "initiator", bdl.Initiator, "bundle", bdl, "error", err)
+					sync.logger.Warn("error on parsing a Gossip bundle",
+						"initiator", bdl.Initiator.ShortString(), "bundle", bdl, "error", err)
 					sync.peerSet.IncreaseInvalidBundlesCounter(bdl.Initiator)
 				}
 
@@ -186,13 +187,15 @@ func (sync *synchronizer) receiveLoop() {
 				}
 				err := sync.processIncomingBundle(bdl)
 				if err != nil {
-					sync.logger.Warn("error on parsing a Stream bundle", "initiator", bdl.Initiator, "bundle", bdl, "error", err)
+					sync.logger.Warn("error on parsing a Stream bundle",
+						"initiator", bdl.Initiator.ShortString(), "bundle", bdl, "error", err)
 					sync.peerSet.IncreaseInvalidBundlesCounter(bdl.Initiator)
 				}
 			case network.EventTypeConnect:
 				ce := e.(*network.ConnectEvent)
 				if err := sync.sayHello(ce.PeerID); err != nil {
-					sync.logger.Warn("sending Hello message failed", "to", ce.PeerID, "error", err)
+					sync.logger.Warn("sending Hello message failed",
+						"to", ce.PeerID.ShortString(), "error", err)
 				}
 			case network.EventTypeDisconnect:
 				de := e.(*network.DisconnectEvent)
@@ -207,7 +210,8 @@ func (sync *synchronizer) processIncomingBundle(bdl *bundle.Bundle) error {
 		return nil
 	}
 
-	sync.logger.Info("received a bundle", "initiator", bdl.Initiator, "bundle", bdl)
+	sync.logger.Info("received a bundle",
+		"initiator", bdl.Initiator.ShortString(), "bundle", bdl)
 	h := sync.handlers[bdl.Message.Type()]
 	if h == nil {
 		return errors.Errorf(errors.ErrInvalidMessage, "invalid message type: %v", bdl.Message.Type())
@@ -296,11 +300,13 @@ func (sync *synchronizer) sendTo(msg message.Message, to peer.ID) error {
 
 		err := sync.network.SendTo(data, to)
 		if err != nil {
-			sync.logger.Warn("error on sending bundle", "bundle", bdl, "error", err, "to", to)
+			sync.logger.Warn("error on sending bundle",
+				"bundle", bdl, "to", to.ShortString(), "error", err)
 
 			return err
 		}
-		sync.logger.Info("sending bundle to a peer", "bundle", bdl, "to", to)
+		sync.logger.Info("sending bundle to a peer",
+			"bundle", bdl, "to", to.ShortString())
 	}
 	return nil
 }
@@ -357,7 +363,7 @@ func (sync *synchronizer) downloadBlocks(from uint32, onlyNodeNetwork bool) {
 		}
 
 		count := LatestBlockInterval
-		sync.logger.Debug("sending download request", "from", from+1, "count", count, "pid", p.PeerID)
+		sync.logger.Debug("sending download request", "from", from+1, "count", count, "pid", p.PeerID.ShortString())
 		session := sync.peerSet.OpenSession(p.PeerID)
 		msg := message.NewBlocksRequestMessage(session.SessionID(), from+1, count)
 		err := sync.sendTo(msg, p.PeerID)

util/logger/logger_test.go

@@ -3,12 +3,8 @@ package logger
 import (
 	"bytes"
 	"fmt"
-	"os"
-	"path/filepath"
-	"strings"
 	"testing"
 
-	"github.com/pactus-project/pactus/util"
 	"github.com/rs/zerolog/log"
 	"github.com/stretchr/testify/assert"
 )
@@ -85,34 +81,3 @@ func TestLogger(t *testing.T) {
 	assert.Contains(t, out, "warn")
 	assert.Contains(t, out, "error")
 }
-
-func TestRotating(t *testing.T) {
-	tempDir := util.TempDirPath()
-	fmt.Println(tempDir)
-	MaxLogSize = 1
-	LogFilename = filepath.Join(tempDir, "pactus.log")
-	c := DefaultConfig()
-	InitGlobalLogger(c)
-	logger := NewSubLogger("test", nil)
-
-	for i := 0; i < 1000; i++ {
-		logger.Info(strings.Repeat("l", 1024))
-	}
-
-	assert.True(t, hasGzFile(tempDir), "log didn't rotate")
-}
-
-func hasGzFile(dir string) bool {
-	files, err := os.ReadDir(dir)
-	if err != nil {
-		return false
-	}
-
-	for _, file := range files {
-		if !file.IsDir() && strings.HasSuffix(file.Name(), ".gz") {
-			return true
-		}
-	}
-
-	return false
-}