feat: normalize message logging

Author: Stebalien

internal/messagequeue/messagequeue.go

@@ -466,23 +466,43 @@ func (mq *MessageQueue) simulateDontHaveWithTimeout(wantlist []bsmsg.Entry) {
 
 func (mq *MessageQueue) logOutgoingMessage(wantlist []bsmsg.Entry) {
 	// Save some CPU cycles and allocations if log level is higher than debug
-	if ce := sflog.Check(zap.DebugLevel, "Bitswap -> send wants"); ce == nil {
+	if ce := sflog.Check(zap.DebugLevel, "sent message"); ce == nil {
 		return
 	}
 
 	self := mq.network.Self()
 	for _, e := range wantlist {
 		if e.Cancel {
 			if e.WantType == pb.Message_Wantlist_Have {
-				log.Debugw("Bitswap -> cancel-have", "local", self, "to", mq.p, "cid", e.Cid)
+				log.Debugw("sent message",
+					"type", "CANCEL_WANT_HAVE",
+					"cid", e.Cid,
+					"local", self,
+					"to", mq.p,
+				)
 			} else {
-				log.Debugw("Bitswap -> cancel-block", "local", self, "to", mq.p, "cid", e.Cid)
+				log.Debugw("sent message",
+					"type", "CANCEL_WANT_BLOCK",
+					"cid", e.Cid,
+					"local", self,
+					"to", mq.p,
+				)
 			}
 		} else {
 			if e.WantType == pb.Message_Wantlist_Have {
-				log.Debugw("Bitswap -> want-have", "local", self, "to", mq.p, "cid", e.Cid)
+				log.Debugw("sent message",
+					"type", "WANT_HAVE",
+					"cid", e.Cid,
+					"local", self,
+					"to", mq.p,
+				)
 			} else {
-				log.Debugw("Bitswap -> want-block", "local", self, "to", mq.p, "cid", e.Cid)
+				log.Debugw("sent message",
+					"type", "WANT_BLOCK",
+					"cid", e.Cid,
+					"local", self,
+					"to", mq.p,
+				)
 			}
 		}
 	}

workers.go

@@ -67,35 +67,40 @@ func (bs *Bitswap) taskWorker(ctx context.Context, id int) {
 }
 
 func (bs *Bitswap) logOutgoingBlocks(env *engine.Envelope) {
-	if ce := sflog.Check(zap.DebugLevel, "Bitswap -> send blocks"); ce == nil {
+	if ce := sflog.Check(zap.DebugLevel, "sent message"); ce == nil {
 		return
 	}
 
+	self := bs.network.Self()
+
 	for _, blockPresence := range env.Message.BlockPresences() {
 		c := blockPresence.Cid
 		switch blockPresence.Type {
 		case pb.Message_Have:
-			log.Debugw("sending message",
+			log.Debugw("sent message",
 				"type", "HAVE",
 				"cid", c,
-				"peer", env.Peer,
+				"local", self,
+				"to", env.Peer,
 			)
 		case pb.Message_DontHave:
-			log.Debugw("sending message",
+			log.Debugw("sent message",
 				"type", "DONT_HAVE",
 				"cid", c,
-				"peer", env.Peer,
+				"local", self,
+				"to", env.Peer,
 			)
 		default:
 			panic(fmt.Sprintf("unrecognized BlockPresence type %v", blockPresence.Type))
 		}
 
 	}
 	for _, block := range env.Message.Blocks() {
-		log.Debugw("sending message",
+		log.Debugw("sent message",
 			"type", "BLOCK",
 			"cid", block.Cid(),
-			"peer", env.Peer,
+			"local", self,
+			"to", env.Peer,
 		)
 	}
 }
@@ -105,8 +110,6 @@ func (bs *Bitswap) sendBlocks(ctx context.Context, env *engine.Envelope) {
 	// throughout the network stack
 	defer env.Sent()
 
-	bs.logOutgoingBlocks(env)
-
 	err := bs.network.SendMessage(ctx, env.Peer, env.Message)
 	if err != nil {
 		log.Debugw("failed to send blocks message",
@@ -116,6 +119,8 @@ func (bs *Bitswap) sendBlocks(ctx context.Context, env *engine.Envelope) {
 		return
 	}
 
+	bs.logOutgoingBlocks(env)
+
 	dataSent := 0
 	blocks := env.Message.Blocks()
 	for _, b := range blocks {