From 24505ab967548a8839e346f8051bee9a2168b1d1 Mon Sep 17 00:00:00 2001 From: Matt Joiner Date: Wed, 20 Mar 2024 12:06:12 +1100 Subject: [PATCH] Fix up some logging --- client.go | 6 +++--- logging.go | 5 ++++- peer.go | 3 +-- peerconn.go | 23 +++++++++++++---------- pexconn.go | 14 ++++++-------- v2hashes.go | 5 ----- 6 files changed, 27 insertions(+), 29 deletions(-) delete mode 100644 v2hashes.go diff --git a/client.go b/client.go index f0587686..c70e4133 100644 --- 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 bfc985c8..f9e68c34 100644 --- 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 71b8e855..733aa018 100644 --- 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 8bf510ea..470ca5cf 100644 --- 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 9254f5e1..b162974c 100644 --- 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 index 0525daa0..00000000 --- a/v2hashes.go +++ /dev/null @@ -1,5 +0,0 @@ -package torrent - -const ( - v2HashesLogName = "v2hashes" -) -- 2.50.0