client.go | 37 ++++++++++++++----------------------- go.mod | 2 +- go.sum | 2 ++ peerconn.go | 4 ++-- portfwd.go | 6 +++--- torrent.go | 10 +++++----- tracker_scraper.go | 2 +- webtorrent/tracker_client.go | 8 ++++---- diff --git a/client.go b/client.go index 36ad98b42df52849bd303de69741ce50bd52850d..30a12ac5c96209c587d68429457b47f8e4943a2a 100644 --- a/client.go +++ b/client.go @@ -146,17 +146,11 @@ fmt.Fprintln(w) } } -const debugLogValue = log.Debug - -func (cl *Client) debugLogFilter(m log.Msg) bool { - if cl.config.Debug { - return true - } - return !m.HasValue(debugLogValue) -} - func (cl *Client) initLogger() { - cl.logger = cl.config.Logger.WithValues(cl).WithFilter(cl.debugLogFilter) + cl.logger = cl.config.Logger.WithValues(cl) + if !cl.config.Debug { + cl.logger = cl.logger.FilterLevel(log.Info) + } } func (cl *Client) announceKey() int32 { @@ -443,13 +437,13 @@ } return } if err != nil { - log.Fmsg("error accepting connection: %s", err).AddValue(debugLogValue).Log(cl.logger) + log.Fmsg("error accepting connection: %s", err).SetLevel(log.Debug).Log(cl.logger) continue } go func() { if reject != nil { torrent.Add("rejected accepted connections", 1) - log.Fmsg("rejecting accepted conn: %v", reject).AddValue(debugLogValue).Log(cl.logger) + log.Fmsg("rejecting accepted conn: %v", reject).SetLevel(log.Debug).Log(cl.logger) conn.Close() } else { go cl.incomingConnection(conn) @@ -458,7 +452,7 @@ log.Fmsg("accepted %q connection at %q from %q", l.Addr().Network(), conn.LocalAddr(), conn.RemoteAddr(), - ).AddValue(debugLogValue).Log(cl.logger) + ).SetLevel(log.Debug).Log(cl.logger) 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) @@ -836,11 +830,10 @@ t, err := cl.receiveHandshakes(c) if err != nil { log.Fmsg( "error receiving handshakes on %v: %s", c, err, - ).AddValue( - debugLogValue, - ).Add( - "network", c.network, - ).Log(cl.logger) + ).SetLevel(log.Debug). + Add( + "network", c.network, + ).Log(cl.logger) torrent.Add("error receiving handshake", 1) cl.lock() cl.onBadAccept(c.remoteAddr) @@ -849,7 +842,7 @@ return } if t == nil { torrent.Add("received handshake for unloaded torrent", 1) - log.Fmsg("received handshake for unloaded torrent").AddValue(debugLogValue).Log(cl.logger) + log.Fmsg("received handshake for unloaded torrent").SetLevel(log.Debug).Log(cl.logger) cl.lock() cl.onBadAccept(c.remoteAddr) cl.unlock() @@ -883,7 +876,7 @@ if connIsIpv6(c.conn) { torrent.Add("completed handshake over ipv6", 1) } if err := t.addConnection(c); err != nil { - log.Fmsg("error adding connection: %s", err).AddValues(c, debugLogValue).Log(t.logger) + log.Fmsg("error adding connection: %s", err).AddValues(c).SetLevel(log.Debug).Log(t.logger) return } defer t.dropConnection(c) @@ -1251,9 +1244,7 @@ remoteAddr: remoteAddr, network: network, connString: connString, } - c.logger = cl.logger.WithValues(c, - log.Debug, // I want messages to default to debug, and can set it here as it's only used by new code - ).WithText(func(m log.Msg) string { + c.logger = cl.logger.WithValues(c).WithDefaultLevel(log.Debug).WithText(func(m log.Msg) string { return fmt.Sprintf("%v: %s", c, m.Text()) }) c.writerCond.L = cl.locker() diff --git a/go.mod b/go.mod index 0f2e065fb4875cce9c7cbee4d1950f9949cfde2e..79dd78d0752708d9390d1defed8e926482885a7e 100644 --- a/go.mod +++ b/go.mod @@ -6,7 +6,7 @@ github.com/alexflint/go-arg v1.2.0 github.com/anacrolix/dht/v2 v2.5.1-0.20200317023935-129f05e9b752 github.com/anacrolix/envpprof v1.1.0 github.com/anacrolix/go-libutp v1.0.2 - github.com/anacrolix/log v0.6.0 + github.com/anacrolix/log v0.6.1-0.20200416071330-f58a030e6149 github.com/anacrolix/missinggo v1.2.1 github.com/anacrolix/missinggo/perf v1.0.0 github.com/anacrolix/missinggo/v2 v2.4.1-0.20200227072623-f02f6484f997 diff --git a/go.sum b/go.sum index aedd7080db4707c4af729484d5b8a82d0a4186ae..616b4423f082d79200016d7945bead057ab4eaca 100644 --- a/go.sum +++ b/go.sum @@ -53,6 +53,8 @@ github.com/anacrolix/log v0.5.0 h1:SD3p5SJZ77we9rt+YbRsL64SAQTAns+9nSYXxFmVVi8= github.com/anacrolix/log v0.5.0/go.mod h1:lWvLTqzAnCWPJA08T2HCstZi0L1y2Wyvm3FJgwU9jwU= github.com/anacrolix/log v0.6.0 h1:5y+wtTWoecbrAWWuoBCH7UuGFiD6q2jnQxrLK01RC+Q= github.com/anacrolix/log v0.6.0/go.mod h1:lWvLTqzAnCWPJA08T2HCstZi0L1y2Wyvm3FJgwU9jwU= +github.com/anacrolix/log v0.6.1-0.20200416071330-f58a030e6149 h1:3cEyLU9ObAfTnBHCev8uuWGhbHfol8uTwyMRkLIpZGg= +github.com/anacrolix/log v0.6.1-0.20200416071330-f58a030e6149/go.mod h1:s5yBP/j046fm9odtUTbHOfDUq/zh1W8OkPpJtnX0oQI= github.com/anacrolix/missinggo v0.0.0-20180522035225-b4a5853e62ff/go.mod h1:b0p+7cn+rWMIphK1gDH2hrDuwGOcbB6V4VXeSsEfHVk= github.com/anacrolix/missinggo v0.0.0-20180725070939-60ef2fbf63df/go.mod h1:kwGiTUTZ0+p4vAz3VbAI5a30t2YbvemcmspjKwrAz5s= github.com/anacrolix/missinggo v0.2.1-0.20190310234110-9fbdc9f242a8 h1:E2Xb2SBsVzHJ1tNMW9QcckYEQcyBKz1ee8qVjeVRWys= diff --git a/peerconn.go b/peerconn.go index 052dcdc0dbd91cee962af6a9e0f122cd77948f8e..bfc935e7e4005fa8f871e1b89624463b7d451d83 100644 --- a/peerconn.go +++ b/peerconn.go @@ -1082,7 +1082,7 @@ go s.Ping(&pingAddr) }) case pp.Suggest: torrent.Add("suggests received", 1) - log.Fmsg("peer suggested piece %d", msg.Index).AddValues(c, msg.Index, debugLogValue).Log(c.t.logger) + log.Fmsg("peer suggested piece %d", msg.Index).AddValues(c, msg.Index).SetLevel(log.Debug).Log(c.t.logger) c.updateRequests() case pp.HaveAll: err = c.onPeerSentHaveAll() @@ -1093,7 +1093,7 @@ c.deleteRequest(newRequestFromMessage(&msg)) delete(c.validReceiveChunks, newRequestFromMessage(&msg)) case pp.AllowedFast: torrent.Add("allowed fasts received", 1) - log.Fmsg("peer allowed fast: %d", msg.Index).AddValues(c, debugLogValue).Log(c.t.logger) + log.Fmsg("peer allowed fast: %d", msg.Index).AddValues(c).SetLevel(log.Debug).Log(c.t.logger) c.peerAllowedFast.Add(int(msg.Index)) c.updateRequests() case pp.Extended: diff --git a/portfwd.go b/portfwd.go index db5bb7df570c6002e4a16a58f438ea1c94d307ef..2a4da0a6da72265c6ced45f7f57251cda956b725 100644 --- a/portfwd.go +++ b/portfwd.go @@ -10,11 +10,11 @@ func (cl *Client) addPortMapping(d upnp.Device, proto upnp.Protocol, internalPort int, upnpID string) { externalPort, err := d.AddPortMapping(proto, internalPort, internalPort, upnpID, 0) if err != nil { - cl.logger.WithValues(log.Warning).Printf("error adding %s port mapping: %s", proto, err) + cl.logger.WithDefaultLevel(log.Warning).Printf("error adding %s port mapping: %s", proto, err) } else if externalPort != internalPort { - cl.logger.WithValues(log.Warning).Printf("external port %d does not match internal port %d in port mapping", externalPort, internalPort) + cl.logger.WithDefaultLevel(log.Warning).Printf("external port %d does not match internal port %d in port mapping", externalPort, internalPort) } else { - cl.logger.WithValues(log.Info).Printf("forwarded external %s port %d", proto, externalPort) + cl.logger.WithDefaultLevel(log.Info).Printf("forwarded external %s port %d", proto, externalPort) } } diff --git a/torrent.go b/torrent.go index 9435fe63d2f89d808b37f7fe7a7155fc7316ecee..c2da92e2373af9bae84d22916b81bd385c74e078 100644 --- a/torrent.go +++ b/torrent.go @@ -1107,7 +1107,7 @@ if complete && len(p.dirtiers) != 0 { 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).WithValues(debugLogValue).Log(t.logger) + log.Fstr("piece %d completion changed: %+v -> %+v", piece, cached, uncached).SetLevel(log.Debug).Log(t.logger) t.pieceCompletionChanged(piece) } return changed @@ -1338,12 +1338,12 @@ case "ws", "wss": wst := websocketTracker{*u, webtorrent.NewTrackerClient(t.cl.peerID, t.infoHash, t.onWebRtcConn, t.logger.WithText(func(m log.Msg) string { return fmt.Sprintf("%q: %v", u.String(), m.Text()) - }).WithValues(log.Debug))} + }).WithDefaultLevel(log.Debug))} ar := t.announceRequest(tracker.Started) go func() { err := wst.TrackerClient.Run(ar, u.String()) if err != nil { - t.logger.WithValues(log.Error).Printf( + t.logger.WithDefaultLevel(log.Error).Printf( "error running websocket tracker announcer for %q: %v", u.String(), err) } @@ -1471,7 +1471,7 @@ cl.unlock() defer cl.lock() err := t.announceToDht(true, s) if err != nil { - t.logger.WithValues(log.Warning).Printf("error announcing %q to DHT: %s", t, err) + t.logger.WithDefaultLevel(log.Warning).Printf("error announcing %q to DHT: %s", t, err) } }() } @@ -1618,7 +1618,7 @@ return oldMax } func (t *Torrent) pieceHashed(piece pieceIndex, passed bool, hashIoErr error) { - t.logger.Log(log.Fstr("hashed piece %d (passed=%t)", piece, passed).WithValues(debugLogValue)) + t.logger.Log(log.Fstr("hashed piece %d (passed=%t)", piece, passed).SetLevel(log.Debug)) p := t.piece(piece) p.numVerifies++ t.cl.event.Broadcast() diff --git a/tracker_scraper.go b/tracker_scraper.go index ffe4be6cab40f5b834f2665eef367e6c334c8638..ae82da5c0366ba2b9c84604c107ced73b6bfbf2d 100644 --- a/tracker_scraper.go +++ b/tracker_scraper.go @@ -117,7 +117,7 @@ } me.t.cl.rLock() req := me.t.announceRequest(event) me.t.cl.rUnlock() - me.t.logger.WithValues(log.Debug).Printf("announcing to %q: %#v", me.u.String(), req) + me.t.logger.WithDefaultLevel(log.Debug).Printf("announcing to %q: %#v", me.u.String(), req) res, err := tracker.Announce{ HTTPProxy: me.t.cl.config.HTTPProxy, UserAgent: me.t.cl.config.HTTPUserAgent, diff --git a/webtorrent/tracker_client.go b/webtorrent/tracker_client.go index 8039e8ce4af9ecf624d0705b271838ac7b6340be..ca0f90ad448d8c8282334b15d8c2055a4d229de0 100644 --- a/webtorrent/tracker_client.go +++ b/webtorrent/tracker_client.go @@ -55,13 +55,13 @@ if err != nil { return fmt.Errorf("failed to dial tracker: %w", err) } defer t.Close() - c.logger.WithValues(log.Info).Printf("dialed tracker %q", url) + c.logger.WithDefaultLevel(log.Debug).Printf("dialed tracker %q", url) c.tracker = t go func() { err := c.announce(ar) if err != nil { - c.logger.WithValues(log.Error).Printf("error announcing: %v", err) + c.logger.WithDefaultLevel(log.Error).Printf("error announcing: %v", err) } }() return c.trackerReadLoop() @@ -126,7 +126,7 @@ _, message, err := tracker.ReadMessage() if err != nil { return fmt.Errorf("read error: %w", err) } - c.logger.WithValues(log.Debug).Printf("received message from tracker: %q", message) + c.logger.WithDefaultLevel(log.Debug).Printf("received message from tracker: %q", message) var ar AnnounceResponse if err := json.Unmarshal(message, &ar); err != nil { @@ -169,7 +169,7 @@ c.lock.Lock() offer, ok := c.outboundOffers[ar.OfferID] c.lock.Unlock() if !ok { - c.logger.WithValues(log.Warning).Printf("could not find offer for id %q", ar.OfferID) + c.logger.WithDefaultLevel(log.Warning).Printf("could not find offer for id %q", ar.OfferID) continue } c.logger.Printf("offer %q got answer %v", ar.OfferID, *ar.Answer)