From a324fbfee3f3a9f134a75e15e13bbeb0c3dcefd8 Mon Sep 17 00:00:00 2001 From: Matt Joiner Date: Sun, 23 Jan 2022 09:37:11 +1100 Subject: [PATCH] Make use of the lazylog branch of anacrolix/log This avoids significant allocations and overhead. --- client.go | 49 +++++++++++++++++++------------------- cmd/torrent/download.go | 8 +++++-- go.mod | 6 ++--- go.sum | 11 ++++++--- peerconn.go | 11 +++++---- reader.go | 2 +- testing.go | 2 ++ torrent.go | 11 ++++++--- tracker/udp/conn-client.go | 2 +- webseed-peer.go | 2 +- 10 files changed, 61 insertions(+), 43 deletions(-) diff --git a/client.go b/client.go index 7586fa80..72dbfe26 100644 --- a/client.go +++ b/client.go @@ -174,19 +174,13 @@ func (cl *Client) WriteStatus(_w io.Writer) { } } -// Filters things that are less than warning from UPnP discovery. -func upnpDiscoverLogFilter(m log.Msg) bool { - level, ok := m.GetLevel() - return !m.HasValue(UpnpDiscoverLogTag) || (!level.LessThan(log.Warning) && ok) -} - func (cl *Client) initLogger() { logger := cl.config.Logger if logger.IsZero() { logger = log.Default - if !cl.config.Debug { - logger = logger.FilterLevel(log.Info).WithFilter(upnpDiscoverLogFilter) - } + } + if cl.config.Debug { + logger = logger.FilterLevel(log.Debug) } cl.logger = logger.WithValues(cl) } @@ -514,22 +508,26 @@ func (cl *Client) acceptConnections(l Listener) { return } if err != nil { - log.Fmsg("error accepting connection: %s", err).SetLevel(log.Debug).Log(cl.logger) + log.Fmsg("error accepting connection: %s", err).LogLevel(log.Debug, cl.logger) continue } go func() { if reject != nil { torrent.Add("rejected accepted connections", 1) - log.Fmsg("rejecting accepted conn: %v", reject).SetLevel(log.Debug).Log(cl.logger) + cl.logger.LazyLog(log.Debug, func() log.Msg { + return log.Fmsg("rejecting accepted conn: %v", reject) + }) conn.Close() } else { go cl.incomingConnection(conn) } - log.Fmsg("accepted %q connection at %q from %q", - l.Addr().Network(), - conn.LocalAddr(), - conn.RemoteAddr(), - ).SetLevel(log.Debug).Log(cl.logger) + cl.logger.LazyLog(log.Debug, func() log.Msg { + return log.Fmsg("accepted %q connection at %q from %q", + l.Addr().Network(), + conn.LocalAddr(), + conn.RemoteAddr(), + ) + }) torrent.Add(fmt.Sprintf("accepted conn remote IP len=%d", len(addrIpOrNil(conn.RemoteAddr()))), 1) torrent.Add(fmt.Sprintf("accepted conn network=%s", conn.RemoteAddr().Network()), 1) torrent.Add(fmt.Sprintf("accepted on %s listener", l.Addr().Network()), 1) @@ -909,12 +907,13 @@ func (cl *Client) runReceivedConn(c *PeerConn) { } t, err := cl.receiveHandshakes(c) if err != nil { - log.Fmsg( - "error receiving handshakes on %v: %s", c, err, - ).SetLevel(log.Debug). - Add( + cl.logger.LazyLog(log.Debug, func() log.Msg { + return log.Fmsg( + "error receiving handshakes on %v: %s", c, err, + ).Add( "network", c.Network, - ).Log(cl.logger) + ) + }) torrent.Add("error receiving handshake", 1) cl.lock() cl.onBadAccept(c.RemoteAddr) @@ -923,7 +922,9 @@ func (cl *Client) runReceivedConn(c *PeerConn) { } if t == nil { torrent.Add("received handshake for unloaded torrent", 1) - log.Fmsg("received handshake for unloaded torrent").SetLevel(log.Debug).Log(cl.logger) + cl.logger.LazyLog(log.Debug, func() log.Msg { + return log.Fmsg("received handshake for unloaded torrent") + }) cl.lock() cl.onBadAccept(c.RemoteAddr) cl.unlock() @@ -954,7 +955,7 @@ func (cl *Client) runHandshookConn(c *PeerConn, t *Torrent) error { // address, we won't record the remote address as a doppleganger. Instead, the initiator // can record *us* as the doppleganger. } */ - t.logger.WithLevel(log.Debug).Printf("local and remote peer ids are the same") + t.logger.Levelf(log.Debug, "local and remote peer ids are the same") return nil } c.r = deadlineReader{c.conn, c.r} @@ -1186,7 +1187,7 @@ func (cl *Client) newTorrentOpt(opts AddTorrentOpts) (t *Torrent) { gotMetainfoC: make(chan struct{}), } t.networkingEnabled.Set() - t.logger = cl.logger.WithContextValue(t) + t.logger = cl.logger.WithContextValue(t).WithNames("torrent", t.infoHash.HexString()) if opts.ChunkSize == 0 { opts.ChunkSize = defaultChunkSize } diff --git a/cmd/torrent/download.go b/cmd/torrent/download.go index f049a290..843dadf0 100644 --- a/cmd/torrent/download.go +++ b/cmd/torrent/download.go @@ -255,8 +255,12 @@ func downloadErr(flags downloadFlags) error { if flags.DownloadRate != nil { clientConfig.DownloadRateLimiter = rate.NewLimiter(rate.Limit(*flags.DownloadRate), 1<<16) } - if flags.Quiet { - clientConfig.Logger = log.Discard + { + logger := log.Default.WithNames("main", "client") + if flags.Quiet { + logger = logger.FilterLevel(log.Critical) + } + clientConfig.Logger = logger } if flags.RequireFastExtension { clientConfig.MinPeerExtensions.SetBit(pp.ExtensionBitFast, true) diff --git a/go.mod b/go.mod index ddc01847..251276ab 100644 --- a/go.mod +++ b/go.mod @@ -7,11 +7,11 @@ require ( github.com/alexflint/go-arg v1.4.2 github.com/anacrolix/args v0.4.1-0.20211104085705-59f0fe94eb8f github.com/anacrolix/chansync v0.3.0 - github.com/anacrolix/dht/v2 v2.14.1-0.20211220010335-4062f7927abf + github.com/anacrolix/dht/v2 v2.15.2-0.20220123034220-0538803801cb github.com/anacrolix/envpprof v1.1.1 github.com/anacrolix/fuse v0.2.0 github.com/anacrolix/go-libutp v1.1.0 - github.com/anacrolix/log v0.10.0 + github.com/anacrolix/log v0.10.1-0.20220123034749-3920702c17f8 github.com/anacrolix/missinggo v1.3.0 github.com/anacrolix/missinggo/perf v1.0.0 github.com/anacrolix/missinggo/v2 v2.5.2 @@ -19,7 +19,7 @@ require ( github.com/anacrolix/squirrel v0.4.0 github.com/anacrolix/sync v0.4.0 github.com/anacrolix/tagflag v1.3.0 - github.com/anacrolix/upnp v0.1.2-0.20200416075019-5e9378ed1425 + github.com/anacrolix/upnp v0.1.3-0.20220123035249-922794e51c96 github.com/anacrolix/utp v0.1.0 github.com/bradfitz/iter v0.0.0-20191230175014-e8f45d346db8 github.com/davecgh/go-spew v1.1.1 diff --git a/go.sum b/go.sum index 7bbf1057..0d713116 100644 --- a/go.sum +++ b/go.sum @@ -104,8 +104,9 @@ github.com/anacrolix/dht/v2 v2.9.1/go.mod h1:ZyYcIQinN/TE3oKONCchQOLjhYR786Jaxz3 github.com/anacrolix/dht/v2 v2.10.0/go.mod h1:KC51tqylRYBu82RM5pEYf+g1n7db+F0tOJqSbCjjZWc= github.com/anacrolix/dht/v2 v2.10.5-0.20210902001729-06cc4fe90e53/go.mod h1:zHjijcebN+L7JbzxW0mOraHis+I81EIgsJAAtiw8bQ8= github.com/anacrolix/dht/v2 v2.10.6-0.20211007004332-99263ec9c1c8/go.mod h1:WID4DexLrucfnwzv1OV8REzgoCpyVDwEczxIOrUeFrY= -github.com/anacrolix/dht/v2 v2.14.1-0.20211220010335-4062f7927abf h1:gPdUT2QIlVX37CCRoKzyx5263AqQJIMyDM0b9DiZyR8= github.com/anacrolix/dht/v2 v2.14.1-0.20211220010335-4062f7927abf/go.mod h1:zJgaiAU2yhzmchZE2mY8WyZ64LK/F/D9MAeN0ct73qQ= +github.com/anacrolix/dht/v2 v2.15.2-0.20220123034220-0538803801cb h1:c4e9XiiT0P3uMkONTkpzLVGxz3if5fIn6UB4HTrVlc0= +github.com/anacrolix/dht/v2 v2.15.2-0.20220123034220-0538803801cb/go.mod h1:GCylVI6WTvbxvhY7pBoHiE5dmjfDWkhqbobDpjND01A= github.com/anacrolix/envpprof v0.0.0-20180404065416-323002cec2fa/go.mod h1:KgHhUaQMc8cC0+cEflSgCFNFbKwi5h54gqtVn8yhP7c= github.com/anacrolix/envpprof v1.0.0/go.mod h1:KgHhUaQMc8cC0+cEflSgCFNFbKwi5h54gqtVn8yhP7c= github.com/anacrolix/envpprof v1.0.1/go.mod h1:My7T5oSqVfEn4MD4Meczkw/f5lSIndGAKu/0SM/rkf4= @@ -130,8 +131,9 @@ github.com/anacrolix/log v0.6.1-0.20200416071330-f58a030e6149/go.mod h1:s5yBP/j0 github.com/anacrolix/log v0.7.1-0.20200604014615-c244de44fd2d/go.mod h1:s5yBP/j046fm9odtUTbHOfDUq/zh1W8OkPpJtnX0oQI= github.com/anacrolix/log v0.8.0/go.mod h1:s5yBP/j046fm9odtUTbHOfDUq/zh1W8OkPpJtnX0oQI= github.com/anacrolix/log v0.9.0/go.mod h1:s5yBP/j046fm9odtUTbHOfDUq/zh1W8OkPpJtnX0oQI= -github.com/anacrolix/log v0.10.0 h1:uz9XDnmsw8ZEO/TTRU03lL7I74PlgVRFszYqPZ39WNY= github.com/anacrolix/log v0.10.0/go.mod h1:s5yBP/j046fm9odtUTbHOfDUq/zh1W8OkPpJtnX0oQI= +github.com/anacrolix/log v0.10.1-0.20220123034749-3920702c17f8 h1:o1KNFCLJ6f5SRMVb70SUFiPnNiazVd0gpMxYfYCsvK4= +github.com/anacrolix/log v0.10.1-0.20220123034749-3920702c17f8/go.mod h1:GmnE2c0nvz8pOIPUSC9Rawgefy1sDXqposC2wgtBZE4= github.com/anacrolix/lsan v0.0.0-20211126052245-807000409a62 h1:P04VG6Td13FHMgS5ZBcJX23NPC/fiC4cp9bXwYujdYM= github.com/anacrolix/lsan v0.0.0-20211126052245-807000409a62/go.mod h1:66cFKPCO7Sl4vbFnAaSq7e4OXtdMhRSBagJGWgmpJbM= github.com/anacrolix/missinggo v0.0.0-20180522035225-b4a5853e62ff/go.mod h1:b0p+7cn+rWMIphK1gDH2hrDuwGOcbB6V4VXeSsEfHVk= @@ -168,6 +170,7 @@ github.com/anacrolix/multiless v0.2.0/go.mod h1:TrCLEZfIDbMVfLoQt5tOoiBS/uq4y8+o github.com/anacrolix/publicip v0.2.0/go.mod h1:67G1lVkLo8UjdEcJkwScWVTvlJ35OCDsRJoWXl/wi4g= github.com/anacrolix/squirrel v0.1.0/go.mod h1:YzgVvikMdFD441oTWlNG189bpKabO9Sbf3uCSVgca04= github.com/anacrolix/squirrel v0.1.1-0.20210914065657-81bc5ecdc43a/go.mod h1:YzgVvikMdFD441oTWlNG189bpKabO9Sbf3uCSVgca04= +github.com/anacrolix/squirrel v0.2.1-0.20211119092713-2efaee06d169/go.mod h1:dJyE7VefQvX0KAKMkOQDGOVEs91a+LvXQ2BjEKl/DIw= github.com/anacrolix/squirrel v0.4.0 h1:MOxYwh0mD2rcEJT+N2tFj2Z3dBDrWn6kRxP4qsBxfyk= github.com/anacrolix/squirrel v0.4.0/go.mod h1:dJyE7VefQvX0KAKMkOQDGOVEs91a+LvXQ2BjEKl/DIw= github.com/anacrolix/stm v0.1.0/go.mod h1:ZKz7e7ERWvP0KgL7WXfRjBXHNRhlVRlbBQecqFtPq+A= @@ -209,9 +212,11 @@ github.com/anacrolix/torrent v1.29.0/go.mod h1:40Hf2bWxFqTbTWbrdig57JnmYLCjShbWW github.com/anacrolix/torrent v1.30.2/go.mod h1:vbNxKfaGiNq8edcCaQI1oSNJwh4GMqtMUMF9qOdZ6C0= github.com/anacrolix/torrent v1.31.1-0.20210910222643-d957502528e0/go.mod h1:akZJHHFN8aWH2lcPZQ0I3etujnenwYpUvj36HV9uvAI= github.com/anacrolix/torrent v1.35.1-0.20211104090255-eaeb38b18c6a/go.mod h1:97nxJW8NIeUyGdBvMOAl9cmcxi8xPez3nlE0RwSZcL0= +github.com/anacrolix/torrent v1.40.0/go.mod h1:ejOLXT7fZE8ONHsoIYD7WS4/l6SEwtRGxcsP3dEu/Fk= github.com/anacrolix/upnp v0.1.1/go.mod h1:LXsbsp5h+WGN7YR+0A7iVXm5BL1LYryDev1zuJMWYQo= -github.com/anacrolix/upnp v0.1.2-0.20200416075019-5e9378ed1425 h1:/Wi6l2ONI1FUFWN4cBwHOO90V4ylp4ud/eov6GUcVFk= github.com/anacrolix/upnp v0.1.2-0.20200416075019-5e9378ed1425/go.mod h1:Pz94W3kl8rf+wxH3IbCa9Sq+DTJr8OSbV2Q3/y51vYs= +github.com/anacrolix/upnp v0.1.3-0.20220123035249-922794e51c96 h1:QAVZ3pN/J4/UziniAhJR2OZ9Ox5kOY2053tBbbqUPYA= +github.com/anacrolix/upnp v0.1.3-0.20220123035249-922794e51c96/go.mod h1:Wa6n8cYIdaG35x15aH3Zy6d03f7P728QfdcDeD/IEOs= github.com/anacrolix/utp v0.0.0-20180219060659-9e0e1d1d0572/go.mod h1:MDwc+vsGEq7RMw6lr2GKOEqjWny5hO5OZXRVNaBJ2Dk= github.com/anacrolix/utp v0.1.0 h1:FOpQOmIwYsnENnz7tAGohA+r6iXpRjrq8ssKSre2Cp4= github.com/anacrolix/utp v0.1.0/go.mod h1:MDwc+vsGEq7RMw6lr2GKOEqjWny5hO5OZXRVNaBJ2Dk= diff --git a/peerconn.go b/peerconn.go index 164cdc9c..bc16ae6c 100644 --- a/peerconn.go +++ b/peerconn.go @@ -1096,9 +1096,9 @@ func runSafeExtraneous(f func()) { } func (c *PeerConn) logProtocolBehaviour(level log.Level, format string, arg ...interface{}) { - c.logger.WithLevel(level).WithContextText(fmt.Sprintf( + c.logger.WithContextText(fmt.Sprintf( "peer id %q, ext v %q", c.PeerID, c.PeerClientName.Load(), - )).SkipCallers(1).Printf(format, arg...) + )).SkipCallers(1).Levelf(level, format, arg...) } // Processes incoming BitTorrent wire-protocol messages. The client lock is held upon entry and @@ -1186,10 +1186,11 @@ 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.WithLevel(log.Debug).Printf( + c.logger.Levelf(log.Debug, "%v requests were preserved while being choked (fast=%v)", preservedCount, c.fastEnabled()) + torrent.Add("requestsPreservedThroughChoking", int64(preservedCount)) } if !c.t._pendingPieces.IsEmpty() { @@ -1240,7 +1241,7 @@ func (c *PeerConn) mainReadLoop() (err error) { }) case pp.Suggest: torrent.Add("suggests received", 1) - log.Fmsg("peer suggested piece %d", msg.Index).AddValues(c, msg.Index).SetLevel(log.Debug).Log(c.t.logger) + log.Fmsg("peer suggested piece %d", msg.Index).AddValues(c, msg.Index).LogLevel(log.Debug, c.t.logger) c.updateRequests("suggested") case pp.HaveAll: err = c.onPeerSentHaveAll() @@ -1254,7 +1255,7 @@ func (c *PeerConn) mainReadLoop() (err error) { } case pp.AllowedFast: torrent.Add("allowed fasts received", 1) - log.Fmsg("peer allowed fast: %d", msg.Index).AddValues(c).SetLevel(log.Debug).Log(c.t.logger) + log.Fmsg("peer allowed fast: %d", msg.Index).AddValues(c).LogLevel(log.Debug, c.t.logger) c.updateRequests("PeerConn.mainReadLoop allowed fast") case pp.Extended: err = c.onReadExtendedMsg(msg.ExtendedID, msg.ExtendedPayload) diff --git a/reader.go b/reader.go index a8264ed1..34e0f489 100644 --- a/reader.go +++ b/reader.go @@ -310,7 +310,7 @@ func (r *reader) Seek(off int64, whence int) (newPos int64, err error) { } func (r *reader) log(m log.Msg) { - r.t.logger.Log(m.Skip(1)) + r.t.logger.LogLevel(log.Debug, m.Skip(1)) } // Implementation inspired by https://news.ycombinator.com/item?id=27019613. diff --git a/testing.go b/testing.go index d681796d..684b2eb7 100644 --- a/testing.go +++ b/testing.go @@ -4,6 +4,7 @@ import ( "testing" "time" + "github.com/anacrolix/log" pp "github.com/anacrolix/torrent/peer_protocol" ) @@ -18,6 +19,7 @@ func TestingConfig(t testing.TB) *ClientConfig { cfg.ListenPort = 0 cfg.KeepAliveTimeout = time.Millisecond cfg.MinPeerExtensions.SetBit(pp.ExtensionBitFast, true) + cfg.Logger = log.Default.WithNames(t.Name()) //cfg.Debug = true //cfg.Logger = cfg.Logger.WithText(func(m log.Msg) string { // t := m.Text() diff --git a/torrent.go b/torrent.go index 744c65e4..e148d38b 100644 --- a/torrent.go +++ b/torrent.go @@ -1302,7 +1302,7 @@ func (t *Torrent) updatePieceCompletion(piece pieceIndex) bool { t.logger.Printf("marked piece %v complete but still has dirtiers", piece) } if changed { - log.Fstr("piece %d completion changed: %+v -> %+v", piece, cached, uncached).SetLevel(log.Debug).Log(t.logger) + log.Fstr("piece %d completion changed: %+v -> %+v", piece, cached, uncached).LogLevel(log.Debug, t.logger) t.pieceCompletionChanged(piece, "Torrent.updatePieceCompletion") } return changed @@ -1932,7 +1932,9 @@ func (t *Torrent) SetMaxEstablishedConns(max int) (oldMax int) { } func (t *Torrent) pieceHashed(piece pieceIndex, passed bool, hashIoErr error) { - t.logger.Log(log.Fstr("hashed piece %d (passed=%t)", piece, passed).SetLevel(log.Debug)) + t.logger.LazyLog(log.Debug, func() log.Msg { + return log.Fstr("hashed piece %d (passed=%t)", piece, passed) + }) p := t.piece(piece) p.numVerifies++ t.cl.event.Broadcast() @@ -1947,7 +1949,10 @@ func (t *Torrent) pieceHashed(piece pieceIndex, passed bool, hashIoErr error) { } else { log.Fmsg( "piece %d failed hash: %d connections contributed", piece, len(p.dirtiers), - ).AddValues(t, p).SetLevel(log.Debug).Log(t.logger) + ).AddValues(t, p).LogLevel( + + log.Debug, t.logger) + pieceHashedNotCorrect.Add(1) } } diff --git a/tracker/udp/conn-client.go b/tracker/udp/conn-client.go index f07ae69c..2e1cac79 100644 --- a/tracker/udp/conn-client.go +++ b/tracker/udp/conn-client.go @@ -45,7 +45,7 @@ func (cc *ConnClient) reader() { } err = cc.d.Dispatch(b[:n], addr) if err != nil { - cc.newOpts.Logger.WithLevel(log.Debug).Printf("dispatching packet received on %v: %v", cc.conn.LocalAddr(), err) + cc.newOpts.Logger.Levelf(log.Debug, "dispatching packet received on %v: %v", cc.conn.LocalAddr(), err) } } } diff --git a/webseed-peer.go b/webseed-peer.go index 2486aba0..4f4ca1f6 100644 --- a/webseed-peer.go +++ b/webseed-peer.go @@ -128,7 +128,7 @@ func (ws *webseedPeer) handleUpdateRequests() { } func (ws *webseedPeer) onClose() { - ws.peer.logger.WithLevel(log.Debug).Print("closing") + ws.peer.logger.Levelf(log.Debug, "closing") // Just deleting them means we would have to manually cancel active requests. ws.peer.cancelAllRequests() ws.peer.t.iterPeers(func(p *Peer) { -- 2.44.0