Make use of the lazylog branch of anacrolix/log

This avoids significant allocations and overhead.

diff --git a/client.go b/client.go
index 7586fa80c1f887b15eb0f0193a55aba039f92eeb..72dbfe26b5484fd4496562d9e4bfea659023a324 100644 (file)
--- 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 f049a290fa766c906fc47d6cfd9f00e9b634a0ee..843dadf0582c09f5dc642678fd36e9bfefda9270 100644 (file)
--- 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 ddc018474b27f98f0dec97777a9553b75c4c69b5..251276ab5ee21def10621f8a117674b4941a1b98 100644 (file)
--- 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 7bbf105785357ba757eb7a95c26393ce371b8680..0d7131167d847a02ee8de4c62f31690f593dcdad 100644 (file)
--- 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 164cdc9ca7e71649200f9cbf0fc5d60fd418e9d0..bc16ae6c63cabad8a18680e5ac9da3cb280c4574 100644 (file)
--- 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 a8264ed1d637250db21705180757ec3e4e4ffbdc..34e0f48927b7b466382598897a1537e03bced6d5 100644 (file)
--- 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 d681796d911b8248355945953b2558a1128cd4ff..684b2eb75c8403d2e6759dce985a4a08eae6f970 100644 (file)
--- 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 744c65e409f34fdb0f0b4a7d8de51d218241adaf..e148d38bd98de87ccdccf2ad53e57b79bf780c63 100644 (file)
--- 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 f07ae69c0139b31f0c6d5017328a40d50e73fd70..2e1cac79013ae16a08ea6ca9a2b775147ad066b9 100644 (file)
--- 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 2486aba05882f722b38953f9371a16c9057543df..4f4ca1f60eeadf9759862bf5c4b7f6f640d0f722 100644 (file)
--- 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) {