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)