status-im
/
torrent
mirror of
2
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Lazy logging

This commit is contained in:
Matt Joiner 2022-01-23 09:37:11 +11:00
parent 1cff4fe95e
commit 7a20e9fe8a
10 changed files with 606 additions and 40 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

49
client.go
View File

@ -178,19 +178,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)
}
@ -518,22 +512,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)
@ -913,12 +911,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)
@ -927,7 +926,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()
@ -958,7 +959,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}
@ -1196,7 +1197,7 @@ func (cl *Client) newTorrentOpt(opts AddTorrentOpts) (t *Torrent) {
t.smartBanCache.Hash = sha1.Sum
t.smartBanCache.Init()
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
}

8
cmd/torrent/download.go
View File

@ -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)

12
go.mod
View File

@ -8,7 +8,7 @@ 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.1
github.com/anacrolix/envpprof v1.1.1
github.com/anacrolix/fuse v0.2.0
github.com/anacrolix/generics v0.0.0-20220121083126-c81e77b56d6d
@ -45,7 +45,7 @@ require (
)
require (
github.com/alexflint/go-scalar v1.0.0 // indirect
github.com/alexflint/go-scalar v1.1.0 // indirect
github.com/anacrolix/confluence v1.9.0 // indirect
github.com/anacrolix/mmsg v1.0.0 // indirect
github.com/anacrolix/stm v0.3.0 // indirect
@ -82,7 +82,7 @@ require (
golang.org/x/sync v0.0.0-20210220032951-036812b2e83c // indirect
golang.org/x/sys v0.0.0-20211023085530-d6a326fbbf70 // indirect
golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 // indirect
gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c // indirect
gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect
modernc.org/libc v1.11.82 // indirect
modernc.org/mathutil v1.4.1 // indirect
modernc.org/memory v1.0.5 // indirect
@ -97,3 +97,9 @@ retract (
// peer-requesting doesn't scale
[v1.34.0, v1.38.1]
)
replace github.com/anacrolix/log => ../log
replace github.com/anacrolix/dht/v2 => ../dht
replace github.com/anacrolix/upnp => ../upnp

547
go.sum
View File

File diff suppressed because it is too large Load Diff

11
peerconn.go
View File

@ -1097,9 +1097,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
@ -1187,10 +1187,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() {
@ -1241,7 +1242,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()
@ -1255,7 +1256,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)

2
reader.go
View File

@ -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.

2
testing.go
View File

@ -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()

11
torrent.go
View File

@ -1324,7 +1324,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
@ -1954,7 +1954,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()
@ -1969,7 +1971,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)
}
}

2
tracker/udp/conn-client.go
View File

@ -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)
}
}
}

2
webseed-peer.go
View File

@ -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) {