Fix logging reported in #841

diff --git a/internal/alloclim/r.go b/internal/alloclim/r.go
index b84be66700513ca8aaf64e33b21f25137849dfd9..71a4dd79c16daca8c40c0b8afbd0dc16827072fd 100644 (file)
--- a/internal/alloclim/r.go
+++ b/internal/alloclim/r.go
@@ -7,6 +7,7 @@ import (
        "sync"
 
        "github.com/anacrolix/chansync"
+       "github.com/anacrolix/log"
 )
 
 type Reservation struct {
@@ -75,7 +76,10 @@ func (me *Reservation) wake() bool {
 
 func (me *Reservation) Wait(ctx context.Context) error {
        if me.n > me.l.Max {
-               return fmt.Errorf("reservation for %v exceeds limiter max %v", me.n, me.l.Max)
+               return log.WithLevel(
+                       log.Warning,
+                       fmt.Errorf("reservation for %v exceeds limiter max %v", me.n, me.l.Max),
+               )
        }
        select {
        case <-ctx.Done():

diff --git a/peerconn.go b/peerconn.go
index 26a475e4bca58192739e80f5392f24a5bdc28efa..62f632d5f7f364546d68aceff9b76dbb8aa8de85 100644 (file)
--- a/peerconn.go
+++ b/peerconn.go
@@ -589,7 +589,16 @@ func (c *PeerConn) onReadRequest(r Request, startFetch bool) error {
 }
 
 func (c *PeerConn) peerRequestDataReader(r Request, prs *peerRequestState) {
-       b, err := c.readPeerRequestData(r, prs)
+       // Should we depend on Torrent closure here? I think it's okay to get cancelled from elsewhere,
+       // or fail to read and then cleanup. Also, we used to hang here if the reservation was never
+       // dropped, that was fixed.
+       ctx := context.Background()
+       err := prs.allocReservation.Wait(ctx)
+       if err != nil {
+               c.logger.WithDefaultLevel(log.Debug).Levelf(log.ErrorLevel(err), "waiting for alloc limit reservation: %v", err)
+               return
+       }
+       b, err := c.readPeerRequestData(r)
        c.locker().Lock()
        defer c.locker().Unlock()
        if err != nil {
@@ -615,7 +624,7 @@ func (c *PeerConn) peerRequestDataReadFailed(err error, r Request) {
                // https://github.com/anacrolix/torrent/issues/702#issuecomment-1000953313.
                logLevel = log.Debug
        }
-       c.logger.WithDefaultLevel(logLevel).Printf("error reading chunk for peer Request %v: %v", r, err)
+       c.logger.Levelf(logLevel, "error reading chunk for peer Request %v: %v", r, err)
        if c.t.closed.IsSet() {
                return
        }
@@ -646,20 +655,7 @@ func (c *PeerConn) peerRequestDataReadFailed(err error, r Request) {
        }
 }
 
-func (c *PeerConn) readPeerRequestData(r Request, prs *peerRequestState) ([]byte, error) {
-       // Should we depend on Torrent closure here? I think it's okay to get cancelled from elsewhere,
-       // or fail to read and then cleanup.
-       ctx := context.Background()
-       err := prs.allocReservation.Wait(ctx)
-       if err != nil {
-               if ctx.Err() == nil {
-                       // The error is from the reservation itself. Something is very broken, or we're not
-                       // guarding against excessively large requests.
-                       err = log.WithLevel(log.Critical, err)
-               }
-               err = fmt.Errorf("waiting for alloc limit reservation: %w", err)
-               return nil, err
-       }
+func (c *PeerConn) readPeerRequestData(r Request) ([]byte, error) {
        b := make([]byte, r.Length)
        p := c.t.info.Piece(int(r.Index))
        n, err := c.t.readAt(b, p.Offset()+int64(r.Begin))

diff --git a/testing.go b/testing.go
index d3f04b669e8c679da3df629b2bdb7294d4661afc..6fb5411267e8c486d454ba384d823f59e9ccc6bd 100644 (file)
--- a/testing.go
+++ b/testing.go
@@ -21,6 +21,9 @@ func TestingConfig(t testing.TB) *ClientConfig {
        cfg.KeepAliveTimeout = time.Millisecond
        cfg.MinPeerExtensions.SetBit(pp.ExtensionBitFast, true)
        cfg.Logger = log.Default.WithContextText(t.Name())
+       // 2 would suffice for the greeting test, but 5 is needed for a few other tests. This should be
+       // something slightly higher than the usual chunk size, so it gets tickled in some tests.
+       cfg.MaxAllocPeerRequestDataPerConn = 5
        //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 a2b85a4d474c044addfb827e0624b7ae9e68add8..6cc2e87f1e6db865410a512c9125d631b3ed9e43 100644 (file)
--- a/torrent.go
+++ b/torrent.go
@@ -2189,7 +2189,7 @@ func (t *Torrent) pieceHashed(piece pieceIndex, passed bool, hashIoErr error) {
                        if len(bannableTouchers) >= 1 {
                                c := bannableTouchers[0]
                                if len(bannableTouchers) != 1 {
-                                       t.logger.Levelf(log.Warning, "would have banned %v for touching piece %v after failed piece check", c.remoteIp(), piece)
+                                       t.logger.Levelf(log.Debug, "would have banned %v for touching piece %v after failed piece check", c.remoteIp(), piece)
                                } else {
                                        // Turns out it's still useful to ban peers like this because if there's only a
                                        // single peer for a piece, and we never progress that piece to completion, we