From 0fd282019e85f8ddafc46cbaed6bb83049990ef9 Mon Sep 17 00:00:00 2001
From: Matt Joiner <anacrolix@gmail.com>
Date: Thu, 3 Oct 2019 19:09:55 +1000
Subject: [PATCH] Add some logging for connections and metadata requests

---
 client.go          | 7 +++++++
 connection.go      | 8 ++++++--
 connection_test.go | 4 ++--
 3 files changed, 15 insertions(+), 4 deletions(-)

diff --git a/client.go b/client.go
index 587d973e..6351286c 100644
--- a/client.go
+++ b/client.go
@@ -980,6 +980,7 @@ func (cl *Client) gotMetadataExtensionMsg(payload []byte, t *Torrent, c *connect
 			return nil
 		}
 		start := (1 << 14) * piece
+		c.logger.Printf("sending metadata piece %d", piece)
 		c.Post(t.newMetadataExtensionMessage(c, pp.DataMetadataExtensionMsgType, piece, t.metadataBytes[start:start+t.metadataPieceSize(piece)]))
 		return nil
 	case pp.RejectMetadataExtensionMsgType:
@@ -1228,12 +1229,18 @@ func (cl *Client) newConnection(nc net.Conn, outgoing bool, remoteAddr IpPort, n
 		remoteAddr:      remoteAddr,
 		network:         network,
 	}
+	c.logger = cl.logger.WithValues(c,
+		log.Debug, // I want messages to default to debug, and can set it here as it's only used by new code
+	).WithText(func(m log.Msg) string {
+		return fmt.Sprintf("%v: %s", c, m.Text())
+	})
 	c.writerCond.L = cl.locker()
 	c.setRW(connStatsReadWriter{nc, c})
 	c.r = &rateLimitedReader{
 		l: cl.config.DownloadRateLimiter,
 		r: c.r,
 	}
+	c.logger.Printf("initialized with remote %v over network %v (outgoing=%t)", remoteAddr, network, outgoing)
 	return
 }
 
diff --git a/connection.go b/connection.go
index c2914bbd..cb240826 100644
--- a/connection.go
+++ b/connection.go
@@ -115,6 +115,8 @@ type connection struct {
 	writeBuffer *bytes.Buffer
 	uploadTimer *time.Timer
 	writerCond  sync.Cond
+
+	logger log.Logger
 }
 
 func (cn *connection) updateExpectingChunks() {
@@ -348,6 +350,7 @@ func (cn *connection) requestMetadataPiece(index int) {
 	if index < len(cn.metadataRequests) && cn.metadataRequests[index] {
 		return
 	}
+	cn.logger.Printf("requesting metadata piece %d", index)
 	cn.Post(pp.Message{
 		Type:       pp.Extended,
 		ExtendedID: eID,
@@ -1225,7 +1228,7 @@ func (c *connection) onReadExtendedMsg(id pp.ExtensionNumber, payload []byte) (e
 	case metadataExtendedId:
 		err := cl.gotMetadataExtensionMsg(payload, t, c)
 		if err != nil {
-			return fmt.Errorf("error handling metadata extension message: %s", err)
+			return fmt.Errorf("handling metadata extension message: %w", err)
 		}
 		return nil
 	case pexExtendedId:
@@ -1546,6 +1549,7 @@ func (c *connection) setTorrent(t *Torrent) {
 		panic("connection already associated with a torrent")
 	}
 	c.t = t
+	c.logger.Printf("torrent=%v", t)
 	t.reconcileHandshakeStats(c)
 }
 
@@ -1562,5 +1566,5 @@ func (c *connection) remoteIpPort() IpPort {
 }
 
 func (c *connection) String() string {
-	return fmt.Sprintf("%p", c)
+	return fmt.Sprintf("connection %p", c)
 }
diff --git a/connection_test.go b/connection_test.go
index 56a07f03..661fb998 100644
--- a/connection_test.go
+++ b/connection_test.go
@@ -19,9 +19,8 @@ import (
 // Ensure that no race exists between sending a bitfield, and a subsequent
 // Have that would potentially alter it.
 func TestSendBitfieldThenHave(t *testing.T) {
-	r, w := io.Pipe()
 	cl := Client{
-		config: &ClientConfig{DownloadRateLimiter: unlimited},
+		config: TestingConfig(),
 	}
 	cl.initLogger()
 	c := cl.newConnection(nil, false, IpPort{}, "")
@@ -29,6 +28,7 @@ func TestSendBitfieldThenHave(t *testing.T) {
 	c.t.setInfo(&metainfo.Info{
 		Pieces: make([]byte, metainfo.HashSize*3),
 	})
+	r, w := io.Pipe()
 	c.r = r
 	c.w = w
 	go c.writer(time.Minute)