From 24505ab967548a8839e346f8051bee9a2168b1d1 Mon Sep 17 00:00:00 2001
From: Matt Joiner <anacrolix@gmail.com>
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.51.0