Fix up some logging

diff --git a/client.go b/client.go
index f0587686502ce6bdfab0339874287626eca845ea..c70e413320f963a7b0bccfe1cba4bd7771d29540 100644 (file)
--- a/client.go
+++ b/client.go
@@ -1263,7 +1263,7 @@ func (cl *Client) gotMetadataExtensionMsg(payload []byte, t *Torrent, c *PeerCon
                        return nil
                }
                start := (1 << 14) * piece
-               c.logger.WithDefaultLevel(log.Debug).Printf("sending metadata piece %d", piece)
+               c.protocolLogger.WithDefaultLevel(log.Debug).Printf("sending metadata piece %d", piece)
                c.write(t.newMetadataExtensionMessage(c, pp.DataMetadataExtensionMsgType, piece, t.metadataBytes[start:start+t.metadataPieceSize(piece)]))
                return nil
        case pp.RejectMetadataExtensionMsgType:
@@ -1665,8 +1665,8 @@ func (cl *Client) newConnection(nc net.Conn, opts newConnectionOpts) (c *PeerCon
                }
        }
        c.peerImpl = c
-       c.logger = cl.logger.WithDefaultLevel(log.Warning)
-       c.logger = c.logger.WithContextText(fmt.Sprintf("%T %p", c, c)).WithNames(protocolLoggingName)
+       c.logger = cl.logger.WithDefaultLevel(log.Warning).WithContextText(fmt.Sprintf("%T %p", c, c))
+       c.protocolLogger = c.logger.WithNames(protocolLoggingName)
        c.setRW(connStatsReadWriter{nc, c})
        c.r = &rateLimitedReader{
                l: cl.config.DownloadRateLimiter,

diff --git a/logging.go b/logging.go
index bfc985c833085068883408ee250c0169b53c84b3..f9e68c343ba86a2c5619ad85026b7b60019bc50f 100644 (file)
--- a/logging.go
+++ b/logging.go
@@ -1,3 +1,6 @@
 package torrent
 
-const protocolLoggingName = "protocol"
+const (
+       protocolLoggingName = "protocol"
+       v2HashesLogName     = "v2hashes"
+)

diff --git a/peer.go b/peer.go
index 71b8e855f9c6d5a27f569ab4b64a40a398f882cc..733aa018ef29727d10df21a44e5f3aa54e033cfb 100644 (file)
--- a/peer.go
+++ b/peer.go
@@ -96,8 +96,7 @@ type (
 
                PeerMaxRequests maxRequests // Maximum pending requests the peer allows.
 
-               logger         log.Logger
-               protocolLogger log.Logger
+               logger log.Logger
        }
 
        PeerSource string

diff --git a/peerconn.go b/peerconn.go
index 8bf510ead59dd072e2c891ac25157af9baa222b9..470ca5cfe0b081b5642238b3d5da34d0d5bd8727 100644 (file)
--- a/peerconn.go
+++ b/peerconn.go
@@ -37,6 +37,9 @@ import (
 type PeerConn struct {
        Peer
 
+       // Move to PeerConn?
+       protocolLogger log.Logger
+
        // BEP 52
        v2 bool
 
@@ -248,7 +251,7 @@ func (cn *PeerConn) requestMetadataPiece(index int) {
        if index < len(cn.metadataRequests) && cn.metadataRequests[index] {
                return
        }
-       cn.logger.WithDefaultLevel(log.Debug).Printf("requesting metadata piece %d", index)
+       cn.protocolLogger.WithDefaultLevel(log.Debug).Printf("requesting metadata piece %d", index)
        cn.write(pp.MetadataExtensionRequestMsg(eID, index))
        for index >= len(cn.metadataRequests) {
                cn.metadataRequests = append(cn.metadataRequests, false)
@@ -608,7 +611,7 @@ func (c *PeerConn) onReadRequest(r Request, startFetch bool) error {
        }
        if opt := c.maximumPeerRequestChunkLength(); opt.Ok && int(r.Length) > opt.Value {
                err := fmt.Errorf("peer requested chunk too long (%v)", r.Length)
-               c.logger.Levelf(log.Warning, err.Error())
+               c.protocolLogger.Levelf(log.Warning, err.Error())
                if c.fastEnabled() {
                        c.reject(r)
                        return nil
@@ -701,7 +704,7 @@ func (c *PeerConn) peerRequestDataReadFailed(err error, r Request) {
                        // If fast isn't enabled, I think we would have wiped all peer requests when we last
                        // choked, and requests while we're choking would be ignored. It could be possible that
                        // a peer request data read completed concurrently to it being deleted elsewhere.
-                       c.logger.WithDefaultLevel(log.Warning).Printf("already choking peer, requests might not be rejected correctly")
+                       c.protocolLogger.WithDefaultLevel(log.Warning).Printf("already choking peer, requests might not be rejected correctly")
                }
                // Choking a non-fast peer should cause them to flush all their requests.
                c.choke(c.write)
@@ -725,7 +728,7 @@ func (c *PeerConn) readPeerRequestData(r Request) ([]byte, error) {
 }
 
 func (c *PeerConn) logProtocolBehaviour(level log.Level, format string, arg ...interface{}) {
-       c.logger.WithContextText(fmt.Sprintf(
+       c.protocolLogger.WithContextText(fmt.Sprintf(
                "peer id %q, ext v %q", c.PeerID, c.PeerClientName.Load(),
        )).SkipCallers(1).Levelf(level, format, arg...)
 }
@@ -814,7 +817,7 @@ func (c *PeerConn) mainReadLoop() (err error) {
                        if preservedCount != 0 {
                                // TODO: Yes this is a debug log but I'm not happy with the state of the logging lib
                                // right now.
-                               c.logger.Levelf(log.Debug,
+                               c.protocolLogger.Levelf(log.Debug,
                                        "%v requests were preserved while being choked (fast=%v)",
                                        preservedCount,
                                        c.fastEnabled())
@@ -882,7 +885,7 @@ func (c *PeerConn) mainReadLoop() (err error) {
                        req := newRequestFromMessage(&msg)
                        if !c.remoteRejectedRequest(c.t.requestIndexFromRequest(req)) {
                                err = fmt.Errorf("received invalid reject for request %v", req)
-                               c.logger.Levelf(log.Debug, "%v", err)
+                               c.protocolLogger.Levelf(log.Debug, "%v", err)
                        }
                case pp.AllowedFast:
                        torrent.Add("allowed fasts received", 1)
@@ -929,7 +932,7 @@ func (c *PeerConn) onReadExtendedMsg(id pp.ExtensionNumber, payload []byte) (err
        if id == pp.HandshakeExtendedID {
                var d pp.ExtendedHandshakeMessage
                if err := bencode.Unmarshal(payload, &d); err != nil {
-                       c.logger.Printf("error parsing extended handshake message %q: %s", payload, err)
+                       c.protocolLogger.Printf("error parsing extended handshake message %q: %s", payload, err)
                        return fmt.Errorf("unmarshalling extended handshake payload: %w", err)
                }
                // Trigger this callback after it's been processed. If you want to handle it yourself, you
@@ -1294,7 +1297,7 @@ file:
                                panic(length)
                        }
                        if length%2 != 0 {
-                               pc.logger.Levelf(log.Warning, "requesting odd hashes length %d", length)
+                               pc.protocolLogger.Levelf(log.Warning, "requesting odd hashes length %d", length)
                        }
                        msg := pp.Message{
                                Type:        pp.HashRequest,
@@ -1333,7 +1336,7 @@ func (pc *PeerConn) onReadHashes(msg *pp.Message) (err error) {
                metainfo.HashForPiecePad(int64(pc.t.usualPieceSize())))
        expectedPiecesRoot := file.piecesRoot.Unwrap()
        if root == expectedPiecesRoot {
-               pc.logger.WithNames(v2HashesLogName).Levelf(
+               pc.protocolLogger.WithNames(v2HashesLogName).Levelf(
                        log.Info,
                        "got piece hashes for file %v (num pieces %v)",
                        file, file.numPieces())
@@ -1342,7 +1345,7 @@ func (pc *PeerConn) onReadHashes(msg *pp.Message) (err error) {
                        pc.t.piece(torrentPieceIndex).hashV2.Set(peerHash)
                }
        } else {
-               pc.logger.WithNames(v2HashesLogName).Levelf(
+               pc.protocolLogger.WithNames(v2HashesLogName).Levelf(
                        log.Debug,
                        "peer file piece hashes root mismatch: %x != %x",
                        root, expectedPiecesRoot)

diff --git a/pexconn.go b/pexconn.go
index 9254f5e1876c15ceff293d9f37c687d004d73b5c..b162974c0d348ad403bb5c082a2dbcd3e504e00e 100644 (file)
--- a/pexconn.go
+++ b/pexconn.go
@@ -26,8 +26,7 @@ type pexConnState struct {
        readyfn func()
        torrent *Torrent
        Listed  bool
-       info    log.Logger
-       dbg     log.Logger
+       logger  log.Logger
        // Running record of live connections the remote end of the connection purports to have.
        remoteLiveConns map[netip.AddrPort]g.Option[pp.PexPeerFlags]
        lastRecv        time.Time
@@ -46,8 +45,7 @@ func (s *pexConnState) Init(c *PeerConn) {
        s.xid = xid
        s.last = nil
        s.torrent = c.t
-       s.info = c.t.cl.logger.WithDefaultLevel(log.Info)
-       s.dbg = c.logger.WithDefaultLevel(log.Debug)
+       s.logger = c.logger.WithDefaultLevel(log.Debug).WithNames("pex")
        s.readyfn = c.tickleWriter
        s.gate = make(chan struct{}, 1)
        s.timer = time.AfterFunc(0, func() {
@@ -85,7 +83,7 @@ func (s *pexConnState) Share(postfn messageWriter) bool {
        select {
        case <-s.gate:
                if tx := s.genmsg(); tx != nil {
-                       s.dbg.Print("sending PEX message: ", tx)
+                       s.logger.Print("sending PEX message: ", tx)
                        flow := postfn(tx.Message(s.xid))
                        s.sched(pexInterval)
                        return flow
@@ -128,7 +126,7 @@ func (s *pexConnState) Recv(payload []byte) error {
        if err != nil {
                return fmt.Errorf("unmarshalling pex message: %w", err)
        }
-       s.dbg.Printf("received pex message: %v", rx)
+       s.logger.Printf("received pex message: %v", rx)
        torrent.Add("pex added peers received", int64(len(rx.Added)))
        torrent.Add("pex added6 peers received", int64(len(rx.Added6)))
 
@@ -144,11 +142,11 @@ func (s *pexConnState) Recv(payload []byte) error {
        peers.AppendFromPex(rx.Added6, rx.Added6Flags)
        peers.AppendFromPex(rx.Added, rx.AddedFlags)
        if time.Now().Before(s.torrent.pex.rest) {
-               s.dbg.Printf("in cooldown period, incoming PEX discarded")
+               s.logger.Printf("in cooldown period, incoming PEX discarded")
                return nil
        }
        added := s.torrent.addPeers(peers)
-       s.dbg.Printf("got %v peers over pex, added %v", len(peers), added)
+       s.logger.Printf("got %v peers over pex, added %v", len(peers), added)
 
        if len(peers) > 0 {
                s.torrent.pex.rest = time.Now().Add(pexInterval)

diff --git a/v2hashes.go b/v2hashes.go
deleted file mode 100644 (file)
index 0525daa..0000000
--- a/v2hashes.go
+++ /dev/null
@@ -1,5 +0,0 @@
-package torrent
-
-const (
-       v2HashesLogName = "v2hashes"
-)