From: Matt Joiner <anacrolix@gmail.com>
Date: Sat, 22 Jan 2022 22:37:11 +0000 (+1100)
Subject: Make use of the lazylog branch of anacrolix/log
X-Git-Tag: v1.41.0~14
X-Git-Url: http://www.git.stargrave.org/?a=commitdiff_plain;h=a324fbfee3f3a9f134a75e15e13bbeb0c3dcefd8;p=btrtrc.git
Make use of the lazylog branch of anacrolix/log
This avoids significant allocations and overhead.
---
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) {