Add some logging for connections and metadata requests

diff --git a/client.go b/client.go
index 587d973ea7d921976a5cb81bb5cc02fa5cc05f93..6351286cbeb1ef61f23aecb0eaf4408333053241 100644 (file)
--- 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 c2914bbdaffb4ca605b2b77e05d96fc32884aff3..cb24082625cf9e2f7370f01b2b28bf39581ba8ba 100644 (file)
--- 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 56a07f030918877f457f36c0a7972a87a16876a0..661fb99862238057c11f9cd8aa665c740491a89a 100644 (file)
--- 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)