chore: optimize debug logging a bit

These are all critical paths so we should try to do as little work as possible.

dht.go

@@ -15,6 +15,7 @@ import (
 	"github.com/libp2p/go-libp2p-core/peerstore"
 	"github.com/libp2p/go-libp2p-core/protocol"
 	"github.com/libp2p/go-libp2p-core/routing"
+	"go.uber.org/zap"
 
 	"go.opencensus.io/tag"
 
@@ -34,7 +35,10 @@ import (
 	"github.com/multiformats/go-multihash"
 )
 
-var logger = logging.Logger("dht")
+var (
+	logger     = logging.Logger("dht")
+	baseLogger = logger.Desugar()
+)
 
 // BaseConnMgrScore is the base of the score set on the connection manager "kbucket" tag.
 // It is added with the common prefix length between two peer IDs.
@@ -464,7 +468,9 @@ func (dht *IpfsDHT) putLocal(key string, rec *recpb.Record) error {
 // If we connect to a peer we already have in the RT but do not exchange a query (rare)
 //    Do Nothing.
 func (dht *IpfsDHT) peerFound(ctx context.Context, p peer.ID, queryPeer bool) {
-	logger.Debugw("peer found", "peer", p)
+	if c := baseLogger.Check(zap.DebugLevel, "peer found"); c != nil {
+		c.Write(zap.String("peer", p.String()))
+	}
 	b, err := dht.validRTPeer(p)
 	if err != nil {
 		logger.Errorw("failed to validate if peer is a DHT peer", "peer", p, "error", err)

dht_net.go

@@ -20,6 +20,7 @@ import (
 	"github.com/libp2p/go-msgio"
 	"go.opencensus.io/stats"
 	"go.opencensus.io/tag"
+	"go.uber.org/zap"
 )
 
 var dhtReadMessageTimeout = 10 * time.Second
@@ -97,8 +98,9 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
 			}
 			// This string test is necessary because there isn't a single stream reset error
 			// instance	in use.
-			if err.Error() != "stream reset" {
-				logger.Debugf("error reading message: %#v", err)
+			if c := baseLogger.Check(zap.DebugLevel, "error reading message"); c != nil && err.Error() != "stream reset" {
+				c.Write(zap.String("from", mPeer.String()),
+					zap.Error(err))
 			}
 			if msgLen > 0 {
 				_ = stats.RecordWithTags(ctx,
@@ -113,7 +115,10 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
 		err = req.Unmarshal(msgbytes)
 		r.ReleaseMsg(msgbytes)
 		if err != nil {
-			logger.Debugf("error unmarshaling message: %#v", err)
+			if c := baseLogger.Check(zap.DebugLevel, "error unmarshaling message"); c != nil {
+				c.Write(zap.String("from", mPeer.String()),
+					zap.Error(err))
+			}
 			_ = stats.RecordWithTags(ctx,
 				[]tag.Mutator{tag.Upsert(metrics.KeyMessageType, "UNKNOWN")},
 				metrics.ReceivedMessages.M(1),
@@ -138,37 +143,39 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
 		handler := dht.handlerForMsgType(req.GetType())
 		if handler == nil {
 			stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
-			logger.Warnw("can't handle received message", "from", mPeer, "type", req.GetType())
+			if c := baseLogger.Check(zap.DebugLevel, "can't handle received message"); c != nil {
+				c.Write(zap.String("from", mPeer.String()),
+					zap.Int32("type", int32(req.GetType())))
+			}
 			return false
 		}
 
 		// a peer has queried us, let's add it to RT
 		dht.peerFound(dht.ctx, mPeer, true)
 
-		logger.Debugw("handling message",
-			"type", req.GetType(),
-			"key", req.GetKey(),
-			"from", mPeer,
-		)
+		if c := baseLogger.Check(zap.DebugLevel, "handling message"); c != nil {
+			c.Write(zap.String("from", mPeer.String()),
+				zap.Int32("type", int32(req.GetType())),
+				zap.Binary("key", req.GetKey()))
+		}
 		resp, err := handler(ctx, mPeer, &req)
 		if err != nil {
 			stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
-			logger.Debugw(
-				"error handling message",
-				"type", req.GetType(),
-				"key", req.GetKey(),
-				"from", mPeer,
-				"error", err)
+			if c := baseLogger.Check(zap.DebugLevel, "error handling message"); c != nil {
+				c.Write(zap.String("from", mPeer.String()),
+					zap.Int32("type", int32(req.GetType())),
+					zap.Binary("key", req.GetKey()),
+					zap.Error(err))
+			}
 			return false
 		}
 
-		logger.Debugw(
-			"handled message",
-			"type", req.GetType(),
-			"key", req.GetKey(),
-			"from", mPeer,
-			"time", time.Since(startTime),
-		)
+		if c := baseLogger.Check(zap.DebugLevel, "handled message"); c != nil {
+			c.Write(zap.String("from", mPeer.String()),
+				zap.Int32("type", int32(req.GetType())),
+				zap.Binary("key", req.GetKey()),
+				zap.Duration("time", time.Since(startTime)))
+		}
 
 		if resp == nil {
 			continue
@@ -178,24 +185,23 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool {
 		err = writeMsg(s, resp)
 		if err != nil {
 			stats.Record(ctx, metrics.ReceivedMessageErrors.M(1))
-			logger.Debugw(
-				"error writing response",
-				"type", req.GetType(),
-				"key", req.GetKey(),
-				"from", mPeer,
-				"error", err)
+			if c := baseLogger.Check(zap.DebugLevel, "error writing response"); c != nil {
+				c.Write(zap.String("from", mPeer.String()),
+					zap.Int32("type", int32(req.GetType())),
+					zap.Binary("key", req.GetKey()),
+					zap.Error(err))
+			}
 			return false
 		}
 
 		elapsedTime := time.Since(startTime)
 
-		logger.Debugw(
-			"responded to message",
-			"type", req.GetType(),
-			"key", req.GetKey(),
-			"from", mPeer,
-			"time", elapsedTime,
-		)
+		if c := baseLogger.Check(zap.DebugLevel, "responded to message"); c != nil {
+			c.Write(zap.String("from", mPeer.String()),
+				zap.Int32("type", int32(req.GetType())),
+				zap.Binary("key", req.GetKey()),
+				zap.Duration("time", elapsedTime))
+		}
 
 		latencyMillis := float64(elapsedTime) / float64(time.Millisecond)
 		stats.Record(ctx, metrics.InboundRequestLatency.M(latencyMillis))

go.mod

@@ -34,4 +34,5 @@ require (
 	github.com/stretchr/testify v1.5.1
 	github.com/whyrusleeping/go-keyspace v0.0.0-20160322163242-5b898ac5add1
 	go.opencensus.io v0.22.3
+	go.uber.org/zap v1.10.0
 )

go.sum

@@ -83,7 +83,6 @@ github.com/gxed/hashland/murmur3 v0.0.1 h1:SheiaIt0sda5K+8FLz952/1iWS9zrnKsEJaOJ
 github.com/gxed/hashland/murmur3 v0.0.1/go.mod h1:KjXop02n4/ckmZSnY2+HKcLud/tcmvhST0bie/0lS48=
 github.com/hashicorp/errwrap v1.0.0 h1:hLrqtEDnRye3+sgx6z4qVLNuviH3MR5aQ0ykNJa/UYA=
 github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
-github.com/hashicorp/go-multierror v1.0.0/go.mod h1:dHtQlpGsu+cZNNAkkCN/P3hoUDHhCYQXV3UM06sGGrk=
 github.com/hashicorp/go-multierror v1.1.0 h1:B9UzwGQJehnUY1yNrnwREHc3fGbC2xefo8g4TbElacI=
 github.com/hashicorp/go-multierror v1.1.0/go.mod h1:spPvp8C1qA32ftKqdAHm4hHTbPw+vmowP0z+KUhOZdA=
 github.com/hashicorp/golang-lru v0.5.0/go.mod h1:/m3WP610KZHVQ1SGc6re/UDhFvYD7pJ4Ao+sR/qLZy8=
@@ -279,8 +278,6 @@ github.com/libp2p/go-libp2p-pnet v0.2.0 h1:J6htxttBipJujEjz1y0a5+eYoiPcFHhSYHH6n
 github.com/libp2p/go-libp2p-pnet v0.2.0/go.mod h1:Qqvq6JH/oMZGwqs3N1Fqhv8NVhrdYcO0BW4wssv21LA=
 github.com/libp2p/go-libp2p-record v0.1.2 h1:M50VKzWnmUrk/M5/Dz99qO9Xh4vs8ijsK+7HkJvRP+0=
 github.com/libp2p/go-libp2p-record v0.1.2/go.mod h1:pal0eNcT5nqZaTV7UGhqeGqxFgGdsU/9W//C8dqjQDk=
-github.com/libp2p/go-libp2p-routing-helpers v0.2.0 h1:+QKTsx2Bg0q3oueQ9CopTwKN5NsnF+qEC+sbkSVXnsU=
-github.com/libp2p/go-libp2p-routing-helpers v0.2.0/go.mod h1:Db+7LRSPImkV9fOKsNWVW5IXyy9XDse92lUtO3O+jlo=
 github.com/libp2p/go-libp2p-routing-helpers v0.2.1 h1:tV5fxxkl1cEEFXIv9yl5OGbLjEwngtq1qf5G/beLRvQ=
 github.com/libp2p/go-libp2p-routing-helpers v0.2.1/go.mod h1:rTLUHlGDZbXHANJAWP2xW7ruPNJLj41/GnCBiR+qgjU=
 github.com/libp2p/go-libp2p-secio v0.1.0/go.mod h1:tMJo2w7h3+wN4pgU2LSYeiKPrfqBgkOsdiKK77hE7c8=