]> Sergey Matveev's repositories - btrtrc.git/blob - peerconn.go
Reduce some logging
[btrtrc.git] / peerconn.go
1 package torrent
2
3 import (
4         "bufio"
5         "bytes"
6         "errors"
7         "fmt"
8         "io"
9         "math/rand"
10         "net"
11         "sort"
12         "strconv"
13         "strings"
14         "sync/atomic"
15         "time"
16
17         "github.com/RoaringBitmap/roaring"
18         "github.com/anacrolix/log"
19         "github.com/anacrolix/missinggo/iter"
20         "github.com/anacrolix/missinggo/v2/bitmap"
21         "github.com/anacrolix/multiless"
22
23         "github.com/anacrolix/chansync"
24         "github.com/anacrolix/torrent/bencode"
25         "github.com/anacrolix/torrent/metainfo"
26         "github.com/anacrolix/torrent/mse"
27         pp "github.com/anacrolix/torrent/peer_protocol"
28         request_strategy "github.com/anacrolix/torrent/request-strategy"
29 )
30
31 type PeerSource string
32
33 const (
34         PeerSourceTracker         = "Tr"
35         PeerSourceIncoming        = "I"
36         PeerSourceDhtGetPeers     = "Hg" // Peers we found by searching a DHT.
37         PeerSourceDhtAnnouncePeer = "Ha" // Peers that were announced to us by a DHT.
38         PeerSourcePex             = "X"
39         // The peer was given directly, such as through a magnet link.
40         PeerSourceDirect = "M"
41 )
42
43 type peerRequestState struct {
44         data []byte
45 }
46
47 type PeerRemoteAddr interface {
48         String() string
49 }
50
51 // Since we have to store all the requests in memory, we can't reasonably exceed what would be
52 // indexable with the memory space available.
53 type (
54         maxRequests  = int
55         requestState = request_strategy.PeerRequestState
56 )
57
58 type Peer struct {
59         // First to ensure 64-bit alignment for atomics. See #262.
60         _stats ConnStats
61
62         t *Torrent
63
64         peerImpl
65         callbacks *Callbacks
66
67         outgoing   bool
68         Network    string
69         RemoteAddr PeerRemoteAddr
70         // True if the connection is operating over MSE obfuscation.
71         headerEncrypted bool
72         cryptoMethod    mse.CryptoMethod
73         Discovery       PeerSource
74         trusted         bool
75         closed          chansync.SetOnce
76         // Set true after we've added our ConnStats generated during handshake to
77         // other ConnStat instances as determined when the *Torrent became known.
78         reconciledHandshakeStats bool
79
80         lastMessageReceived     time.Time
81         completedHandshake      time.Time
82         lastUsefulChunkReceived time.Time
83         lastChunkSent           time.Time
84
85         // Stuff controlled by the local peer.
86         needRequestUpdate    string
87         requestState         requestState
88         updateRequestsTimer  *time.Timer
89         lastRequestUpdate    time.Time
90         peakRequests         maxRequests
91         lastBecameInterested time.Time
92         priorInterest        time.Duration
93
94         lastStartedExpectingToReceiveChunks time.Time
95         cumulativeExpectedToReceiveChunks   time.Duration
96         _chunksReceivedWhileExpecting       int64
97
98         choking                                bool
99         piecesReceivedSinceLastRequestUpdate   maxRequests
100         maxPiecesReceivedBetweenRequestUpdates maxRequests
101         // Chunks that we might reasonably expect to receive from the peer. Due to latency, buffering,
102         // and implementation differences, we may receive chunks that are no longer in the set of
103         // requests actually want. This could use a roaring.BSI if the memory use becomes noticeable.
104         validReceiveChunks map[RequestIndex]int
105         // Indexed by metadata piece, set to true if posted and pending a
106         // response.
107         metadataRequests []bool
108         sentHaves        bitmap.Bitmap
109
110         // Stuff controlled by the remote peer.
111         peerInterested        bool
112         peerChoking           bool
113         peerRequests          map[Request]*peerRequestState
114         PeerPrefersEncryption bool // as indicated by 'e' field in extension handshake
115         PeerListenPort        int
116         // The highest possible number of pieces the torrent could have based on
117         // communication with the peer. Generally only useful until we have the
118         // torrent info.
119         peerMinPieces pieceIndex
120         // Pieces we've accepted chunks for from the peer.
121         peerTouchedPieces map[pieceIndex]struct{}
122         peerAllowedFast   roaring.Bitmap
123
124         PeerMaxRequests  maxRequests // Maximum pending requests the peer allows.
125         PeerExtensionIDs map[pp.ExtensionName]pp.ExtensionNumber
126         PeerClientName   atomic.Value
127
128         logger log.Logger
129 }
130
131 // Maintains the state of a BitTorrent-protocol based connection with a peer.
132 type PeerConn struct {
133         Peer
134
135         // A string that should identify the PeerConn's net.Conn endpoints. The net.Conn could
136         // be wrapping WebRTC, uTP, or TCP etc. Used in writing the conn status for peers.
137         connString string
138
139         // See BEP 3 etc.
140         PeerID             PeerID
141         PeerExtensionBytes pp.PeerExtensionBits
142
143         // The actual Conn, used for closing, and setting socket options. Do not use methods on this
144         // while holding any mutexes.
145         conn net.Conn
146         // The Reader and Writer for this Conn, with hooks installed for stats,
147         // limiting, deadlines etc.
148         w io.Writer
149         r io.Reader
150
151         messageWriter peerConnMsgWriter
152
153         uploadTimer *time.Timer
154         pex         pexConnState
155
156         // The pieces the peer has claimed to have.
157         _peerPieces roaring.Bitmap
158         // The peer has everything. This can occur due to a special message, when
159         // we may not even know the number of pieces in the torrent yet.
160         peerSentHaveAll bool
161 }
162
163 func (cn *PeerConn) connStatusString() string {
164         return fmt.Sprintf("%+-55q %s %s", cn.PeerID, cn.PeerExtensionBytes, cn.connString)
165 }
166
167 func (cn *Peer) updateExpectingChunks() {
168         if cn.expectingChunks() {
169                 if cn.lastStartedExpectingToReceiveChunks.IsZero() {
170                         cn.lastStartedExpectingToReceiveChunks = time.Now()
171                 }
172         } else {
173                 if !cn.lastStartedExpectingToReceiveChunks.IsZero() {
174                         cn.cumulativeExpectedToReceiveChunks += time.Since(cn.lastStartedExpectingToReceiveChunks)
175                         cn.lastStartedExpectingToReceiveChunks = time.Time{}
176                 }
177         }
178 }
179
180 func (cn *Peer) expectingChunks() bool {
181         if cn.requestState.Requests.IsEmpty() {
182                 return false
183         }
184         if !cn.requestState.Interested {
185                 return false
186         }
187         if !cn.peerChoking {
188                 return true
189         }
190         haveAllowedFastRequests := false
191         cn.peerAllowedFast.Iterate(func(i uint32) bool {
192                 haveAllowedFastRequests = roaringBitmapRangeCardinality(
193                         &cn.requestState.Requests,
194                         cn.t.pieceRequestIndexOffset(pieceIndex(i)),
195                         cn.t.pieceRequestIndexOffset(pieceIndex(i+1)),
196                 ) == 0
197                 return !haveAllowedFastRequests
198         })
199         return haveAllowedFastRequests
200 }
201
202 func (cn *Peer) remoteChokingPiece(piece pieceIndex) bool {
203         return cn.peerChoking && !cn.peerAllowedFast.Contains(bitmap.BitIndex(piece))
204 }
205
206 // Returns true if the connection is over IPv6.
207 func (cn *PeerConn) ipv6() bool {
208         ip := cn.remoteIp()
209         if ip.To4() != nil {
210                 return false
211         }
212         return len(ip) == net.IPv6len
213 }
214
215 // Returns true the if the dialer/initiator has the lower client peer ID. TODO: Find the
216 // specification for this.
217 func (cn *PeerConn) isPreferredDirection() bool {
218         return bytes.Compare(cn.t.cl.peerID[:], cn.PeerID[:]) < 0 == cn.outgoing
219 }
220
221 // Returns whether the left connection should be preferred over the right one,
222 // considering only their networking properties. If ok is false, we can't
223 // decide.
224 func (l *PeerConn) hasPreferredNetworkOver(r *PeerConn) (left, ok bool) {
225         var ml multiLess
226         ml.NextBool(l.isPreferredDirection(), r.isPreferredDirection())
227         ml.NextBool(!l.utp(), !r.utp())
228         ml.NextBool(l.ipv6(), r.ipv6())
229         return ml.FinalOk()
230 }
231
232 func (cn *Peer) cumInterest() time.Duration {
233         ret := cn.priorInterest
234         if cn.requestState.Interested {
235                 ret += time.Since(cn.lastBecameInterested)
236         }
237         return ret
238 }
239
240 func (cn *PeerConn) peerHasAllPieces() (all, known bool) {
241         if cn.peerSentHaveAll {
242                 return true, true
243         }
244         if !cn.t.haveInfo() {
245                 return false, false
246         }
247         return cn._peerPieces.GetCardinality() == uint64(cn.t.numPieces()), true
248 }
249
250 func (cn *Peer) locker() *lockWithDeferreds {
251         return cn.t.cl.locker()
252 }
253
254 func (cn *Peer) supportsExtension(ext pp.ExtensionName) bool {
255         _, ok := cn.PeerExtensionIDs[ext]
256         return ok
257 }
258
259 // The best guess at number of pieces in the torrent for this peer.
260 func (cn *Peer) bestPeerNumPieces() pieceIndex {
261         if cn.t.haveInfo() {
262                 return cn.t.numPieces()
263         }
264         return cn.peerMinPieces
265 }
266
267 func (cn *Peer) completedString() string {
268         have := pieceIndex(cn.peerPieces().GetCardinality())
269         if all, _ := cn.peerHasAllPieces(); all {
270                 have = cn.bestPeerNumPieces()
271         }
272         return fmt.Sprintf("%d/%d", have, cn.bestPeerNumPieces())
273 }
274
275 func (cn *PeerConn) onGotInfo(info *metainfo.Info) {
276         cn.setNumPieces(info.NumPieces())
277 }
278
279 // Correct the PeerPieces slice length. Return false if the existing slice is invalid, such as by
280 // receiving badly sized BITFIELD, or invalid HAVE messages.
281 func (cn *PeerConn) setNumPieces(num pieceIndex) {
282         cn._peerPieces.RemoveRange(bitmap.BitRange(num), bitmap.ToEnd)
283         cn.peerPiecesChanged()
284 }
285
286 func (cn *PeerConn) peerPieces() *roaring.Bitmap {
287         return &cn._peerPieces
288 }
289
290 func eventAgeString(t time.Time) string {
291         if t.IsZero() {
292                 return "never"
293         }
294         return fmt.Sprintf("%.2fs ago", time.Since(t).Seconds())
295 }
296
297 func (cn *PeerConn) connectionFlags() (ret string) {
298         c := func(b byte) {
299                 ret += string([]byte{b})
300         }
301         if cn.cryptoMethod == mse.CryptoMethodRC4 {
302                 c('E')
303         } else if cn.headerEncrypted {
304                 c('e')
305         }
306         ret += string(cn.Discovery)
307         if cn.utp() {
308                 c('U')
309         }
310         return
311 }
312
313 func (cn *PeerConn) utp() bool {
314         return parseNetworkString(cn.Network).Udp
315 }
316
317 // Inspired by https://github.com/transmission/transmission/wiki/Peer-Status-Text.
318 func (cn *Peer) statusFlags() (ret string) {
319         c := func(b byte) {
320                 ret += string([]byte{b})
321         }
322         if cn.requestState.Interested {
323                 c('i')
324         }
325         if cn.choking {
326                 c('c')
327         }
328         c('-')
329         ret += cn.connectionFlags()
330         c('-')
331         if cn.peerInterested {
332                 c('i')
333         }
334         if cn.peerChoking {
335                 c('c')
336         }
337         return
338 }
339
340 func (cn *Peer) downloadRate() float64 {
341         num := cn._stats.BytesReadUsefulData.Int64()
342         if num == 0 {
343                 return 0
344         }
345         return float64(num) / cn.totalExpectingTime().Seconds()
346 }
347
348 func (cn *Peer) numRequestsByPiece() (ret map[pieceIndex]int) {
349         ret = make(map[pieceIndex]int)
350         cn.requestState.Requests.Iterate(func(x uint32) bool {
351                 ret[pieceIndex(x/cn.t.chunksPerRegularPiece())]++
352                 return true
353         })
354         return
355 }
356
357 func (cn *Peer) writeStatus(w io.Writer, t *Torrent) {
358         // \t isn't preserved in <pre> blocks?
359         if cn.closed.IsSet() {
360                 fmt.Fprint(w, "CLOSED: ")
361         }
362         fmt.Fprintln(w, cn.connStatusString())
363         prio, err := cn.peerPriority()
364         prioStr := fmt.Sprintf("%08x", prio)
365         if err != nil {
366                 prioStr += ": " + err.Error()
367         }
368         fmt.Fprintf(w, "    bep40-prio: %v\n", prioStr)
369         fmt.Fprintf(w, "    last msg: %s, connected: %s, last helpful: %s, itime: %s, etime: %s\n",
370                 eventAgeString(cn.lastMessageReceived),
371                 eventAgeString(cn.completedHandshake),
372                 eventAgeString(cn.lastHelpful()),
373                 cn.cumInterest(),
374                 cn.totalExpectingTime(),
375         )
376         fmt.Fprintf(w,
377                 "    %s completed, %d pieces touched, good chunks: %v/%v:%v reqq: %d+%v/(%d/%d):%d/%d, flags: %s, dr: %.1f KiB/s\n",
378                 cn.completedString(),
379                 len(cn.peerTouchedPieces),
380                 &cn._stats.ChunksReadUseful,
381                 &cn._stats.ChunksRead,
382                 &cn._stats.ChunksWritten,
383                 cn.requestState.Requests.GetCardinality(),
384                 cn.requestState.Cancelled.GetCardinality(),
385                 cn.nominalMaxRequests(),
386                 cn.PeerMaxRequests,
387                 len(cn.peerRequests),
388                 localClientReqq,
389                 cn.statusFlags(),
390                 cn.downloadRate()/(1<<10),
391         )
392         fmt.Fprintf(w, "    requested pieces:")
393         type pieceNumRequestsType struct {
394                 piece       pieceIndex
395                 numRequests int
396         }
397         var pieceNumRequests []pieceNumRequestsType
398         for piece, count := range cn.numRequestsByPiece() {
399                 pieceNumRequests = append(pieceNumRequests, pieceNumRequestsType{piece, count})
400         }
401         sort.Slice(pieceNumRequests, func(i, j int) bool {
402                 return pieceNumRequests[i].piece < pieceNumRequests[j].piece
403         })
404         for _, elem := range pieceNumRequests {
405                 fmt.Fprintf(w, " %v(%v)", elem.piece, elem.numRequests)
406         }
407         fmt.Fprintf(w, "\n")
408 }
409
410 func (p *Peer) close() {
411         if !p.closed.Set() {
412                 return
413         }
414         if p.updateRequestsTimer != nil {
415                 p.updateRequestsTimer.Stop()
416         }
417         p.peerImpl.onClose()
418         if p.t != nil {
419                 p.t.decPeerPieceAvailability(p)
420         }
421         for _, f := range p.callbacks.PeerClosed {
422                 f(p)
423         }
424 }
425
426 func (cn *PeerConn) onClose() {
427         if cn.pex.IsEnabled() {
428                 cn.pex.Close()
429         }
430         cn.tickleWriter()
431         if cn.conn != nil {
432                 go cn.conn.Close()
433         }
434         if cb := cn.callbacks.PeerConnClosed; cb != nil {
435                 cb(cn)
436         }
437 }
438
439 // Peer definitely has a piece, for purposes of requesting. So it's not sufficient that we think
440 // they do (known=true).
441 func (cn *Peer) peerHasPiece(piece pieceIndex) bool {
442         if all, known := cn.peerHasAllPieces(); all && known {
443                 return true
444         }
445         return cn.peerPieces().ContainsInt(piece)
446 }
447
448 // 64KiB, but temporarily less to work around an issue with WebRTC. TODO: Update when
449 // https://github.com/pion/datachannel/issues/59 is fixed.
450 const (
451         writeBufferHighWaterLen = 1 << 15
452         writeBufferLowWaterLen  = writeBufferHighWaterLen / 2
453 )
454
455 // Writes a message into the write buffer. Returns whether it's okay to keep writing. Writing is
456 // done asynchronously, so it may be that we're not able to honour backpressure from this method.
457 func (cn *PeerConn) write(msg pp.Message) bool {
458         torrent.Add(fmt.Sprintf("messages written of type %s", msg.Type.String()), 1)
459         // We don't need to track bytes here because the connection's Writer has that behaviour injected
460         // (although there's some delay between us buffering the message, and the connection writer
461         // flushing it out.).
462         notFull := cn.messageWriter.write(msg)
463         // Last I checked only Piece messages affect stats, and we don't write those.
464         cn.wroteMsg(&msg)
465         cn.tickleWriter()
466         return notFull
467 }
468
469 func (cn *PeerConn) requestMetadataPiece(index int) {
470         eID := cn.PeerExtensionIDs[pp.ExtensionNameMetadata]
471         if eID == pp.ExtensionDeleteNumber {
472                 return
473         }
474         if index < len(cn.metadataRequests) && cn.metadataRequests[index] {
475                 return
476         }
477         cn.logger.WithDefaultLevel(log.Debug).Printf("requesting metadata piece %d", index)
478         cn.write(pp.MetadataExtensionRequestMsg(eID, index))
479         for index >= len(cn.metadataRequests) {
480                 cn.metadataRequests = append(cn.metadataRequests, false)
481         }
482         cn.metadataRequests[index] = true
483 }
484
485 func (cn *PeerConn) requestedMetadataPiece(index int) bool {
486         return index < len(cn.metadataRequests) && cn.metadataRequests[index]
487 }
488
489 var (
490         interestedMsgLen = len(pp.Message{Type: pp.Interested}.MustMarshalBinary())
491         requestMsgLen    = len(pp.Message{Type: pp.Request}.MustMarshalBinary())
492         // This is the maximum request count that could fit in the write buffer if it's at or below the
493         // low water mark when we run maybeUpdateActualRequestState.
494         maxLocalToRemoteRequests = (writeBufferHighWaterLen - writeBufferLowWaterLen - interestedMsgLen) / requestMsgLen
495 )
496
497 // The actual value to use as the maximum outbound requests.
498 func (cn *Peer) nominalMaxRequests() maxRequests {
499         return maxRequests(maxInt(1, minInt(cn.PeerMaxRequests, cn.peakRequests*2, maxLocalToRemoteRequests)))
500 }
501
502 func (cn *Peer) totalExpectingTime() (ret time.Duration) {
503         ret = cn.cumulativeExpectedToReceiveChunks
504         if !cn.lastStartedExpectingToReceiveChunks.IsZero() {
505                 ret += time.Since(cn.lastStartedExpectingToReceiveChunks)
506         }
507         return
508 }
509
510 func (cn *PeerConn) onPeerSentCancel(r Request) {
511         if _, ok := cn.peerRequests[r]; !ok {
512                 torrent.Add("unexpected cancels received", 1)
513                 return
514         }
515         if cn.fastEnabled() {
516                 cn.reject(r)
517         } else {
518                 delete(cn.peerRequests, r)
519         }
520 }
521
522 func (cn *PeerConn) choke(msg messageWriter) (more bool) {
523         if cn.choking {
524                 return true
525         }
526         cn.choking = true
527         more = msg(pp.Message{
528                 Type: pp.Choke,
529         })
530         if cn.fastEnabled() {
531                 for r := range cn.peerRequests {
532                         // TODO: Don't reject pieces in allowed fast set.
533                         cn.reject(r)
534                 }
535         } else {
536                 cn.peerRequests = nil
537         }
538         return
539 }
540
541 func (cn *PeerConn) unchoke(msg func(pp.Message) bool) bool {
542         if !cn.choking {
543                 return true
544         }
545         cn.choking = false
546         return msg(pp.Message{
547                 Type: pp.Unchoke,
548         })
549 }
550
551 func (cn *Peer) setInterested(interested bool) bool {
552         if cn.requestState.Interested == interested {
553                 return true
554         }
555         cn.requestState.Interested = interested
556         if interested {
557                 cn.lastBecameInterested = time.Now()
558         } else if !cn.lastBecameInterested.IsZero() {
559                 cn.priorInterest += time.Since(cn.lastBecameInterested)
560         }
561         cn.updateExpectingChunks()
562         // log.Printf("%p: setting interest: %v", cn, interested)
563         return cn.writeInterested(interested)
564 }
565
566 func (pc *PeerConn) writeInterested(interested bool) bool {
567         return pc.write(pp.Message{
568                 Type: func() pp.MessageType {
569                         if interested {
570                                 return pp.Interested
571                         } else {
572                                 return pp.NotInterested
573                         }
574                 }(),
575         })
576 }
577
578 // The function takes a message to be sent, and returns true if more messages
579 // are okay.
580 type messageWriter func(pp.Message) bool
581
582 // This function seems to only used by Peer.request. It's all logic checks, so maybe we can no-op it
583 // when we want to go fast.
584 func (cn *Peer) shouldRequest(r RequestIndex) error {
585         pi := pieceIndex(r / cn.t.chunksPerRegularPiece())
586         if cn.requestState.Cancelled.Contains(r) {
587                 return errors.New("request is cancelled and waiting acknowledgement")
588         }
589         if !cn.peerHasPiece(pi) {
590                 return errors.New("requesting piece peer doesn't have")
591         }
592         if !cn.t.peerIsActive(cn) {
593                 panic("requesting but not in active conns")
594         }
595         if cn.closed.IsSet() {
596                 panic("requesting when connection is closed")
597         }
598         if cn.t.hashingPiece(pi) {
599                 panic("piece is being hashed")
600         }
601         if cn.t.pieceQueuedForHash(pi) {
602                 panic("piece is queued for hash")
603         }
604         if cn.peerChoking && !cn.peerAllowedFast.Contains(bitmap.BitIndex(pi)) {
605                 // This could occur if we made a request with the fast extension, and then got choked and
606                 // haven't had the request rejected yet.
607                 if !cn.requestState.Requests.Contains(r) {
608                         panic("peer choking and piece not allowed fast")
609                 }
610         }
611         return nil
612 }
613
614 func (cn *Peer) mustRequest(r RequestIndex) bool {
615         more, err := cn.request(r)
616         if err != nil {
617                 panic(err)
618         }
619         return more
620 }
621
622 func (cn *Peer) request(r RequestIndex) (more bool, err error) {
623         if err := cn.shouldRequest(r); err != nil {
624                 panic(err)
625         }
626         if cn.requestState.Requests.Contains(r) {
627                 return true, nil
628         }
629         if maxRequests(cn.requestState.Requests.GetCardinality()) >= cn.nominalMaxRequests() {
630                 return true, errors.New("too many outstanding requests")
631         }
632         cn.requestState.Requests.Add(r)
633         if cn.validReceiveChunks == nil {
634                 cn.validReceiveChunks = make(map[RequestIndex]int)
635         }
636         cn.validReceiveChunks[r]++
637         cn.t.pendingRequests[r] = cn
638         cn.t.lastRequested[r] = time.Now()
639         cn.updateExpectingChunks()
640         ppReq := cn.t.requestIndexToRequest(r)
641         for _, f := range cn.callbacks.SentRequest {
642                 f(PeerRequestEvent{cn, ppReq})
643         }
644         return cn.peerImpl._request(ppReq), nil
645 }
646
647 func (me *PeerConn) _request(r Request) bool {
648         return me.write(pp.Message{
649                 Type:   pp.Request,
650                 Index:  r.Index,
651                 Begin:  r.Begin,
652                 Length: r.Length,
653         })
654 }
655
656 func (me *Peer) cancel(r RequestIndex) {
657         if !me.deleteRequest(r) {
658                 panic("request not existing should have been guarded")
659         }
660         if me._cancel(r) {
661                 if !me.requestState.Cancelled.CheckedAdd(r) {
662                         panic("request already cancelled")
663                 }
664         }
665         me.decPeakRequests()
666         if me.isLowOnRequests() {
667                 me.updateRequests("Peer.cancel")
668         }
669 }
670
671 func (me *PeerConn) _cancel(r RequestIndex) bool {
672         me.write(makeCancelMessage(me.t.requestIndexToRequest(r)))
673         // Transmission does not send rejects for received cancels. See
674         // https://github.com/transmission/transmission/pull/2275.
675         return me.fastEnabled() && !me.remoteIsTransmission()
676 }
677
678 func (cn *PeerConn) fillWriteBuffer() {
679         if cn.messageWriter.writeBuffer.Len() > writeBufferLowWaterLen {
680                 // Fully committing to our max requests requires sufficient space (see
681                 // maxLocalToRemoteRequests). Flush what we have instead. We also prefer always to make
682                 // requests than to do PEX or upload, so we short-circuit before handling those. Any update
683                 // request reason will not be cleared, so we'll come right back here when there's space. We
684                 // can't do this in maybeUpdateActualRequestState because it's a method on Peer and has no
685                 // knowledge of write buffers.
686         }
687         cn.maybeUpdateActualRequestState()
688         if cn.pex.IsEnabled() {
689                 if flow := cn.pex.Share(cn.write); !flow {
690                         return
691                 }
692         }
693         cn.upload(cn.write)
694 }
695
696 func (cn *PeerConn) have(piece pieceIndex) {
697         if cn.sentHaves.Get(bitmap.BitIndex(piece)) {
698                 return
699         }
700         cn.write(pp.Message{
701                 Type:  pp.Have,
702                 Index: pp.Integer(piece),
703         })
704         cn.sentHaves.Add(bitmap.BitIndex(piece))
705 }
706
707 func (cn *PeerConn) postBitfield() {
708         if cn.sentHaves.Len() != 0 {
709                 panic("bitfield must be first have-related message sent")
710         }
711         if !cn.t.haveAnyPieces() {
712                 return
713         }
714         cn.write(pp.Message{
715                 Type:     pp.Bitfield,
716                 Bitfield: cn.t.bitfield(),
717         })
718         cn.sentHaves = bitmap.Bitmap{cn.t._completedPieces.Clone()}
719 }
720
721 // Sets a reason to update requests, and if there wasn't already one, handle it.
722 func (cn *Peer) updateRequests(reason string) {
723         if cn.needRequestUpdate != "" {
724                 return
725         }
726         if reason != peerUpdateRequestsTimerReason && !cn.isLowOnRequests() {
727                 return
728         }
729         cn.needRequestUpdate = reason
730         cn.handleUpdateRequests()
731 }
732
733 func (cn *PeerConn) handleUpdateRequests() {
734         // The writer determines the request state as needed when it can write.
735         cn.tickleWriter()
736 }
737
738 // Emits the indices in the Bitmaps bms in order, never repeating any index.
739 // skip is mutated during execution, and its initial values will never be
740 // emitted.
741 func iterBitmapsDistinct(skip *bitmap.Bitmap, bms ...bitmap.Bitmap) iter.Func {
742         return func(cb iter.Callback) {
743                 for _, bm := range bms {
744                         if !iter.All(
745                                 func(_i interface{}) bool {
746                                         i := _i.(int)
747                                         if skip.Contains(bitmap.BitIndex(i)) {
748                                                 return true
749                                         }
750                                         skip.Add(bitmap.BitIndex(i))
751                                         return cb(i)
752                                 },
753                                 bm.Iter,
754                         ) {
755                                 return
756                         }
757                 }
758         }
759 }
760
761 func (cn *Peer) peerPiecesChanged() {
762         cn.t.maybeDropMutuallyCompletePeer(cn)
763 }
764
765 func (cn *PeerConn) raisePeerMinPieces(newMin pieceIndex) {
766         if newMin > cn.peerMinPieces {
767                 cn.peerMinPieces = newMin
768         }
769 }
770
771 func (cn *PeerConn) peerSentHave(piece pieceIndex) error {
772         if cn.t.haveInfo() && piece >= cn.t.numPieces() || piece < 0 {
773                 return errors.New("invalid piece")
774         }
775         if cn.peerHasPiece(piece) {
776                 return nil
777         }
778         cn.raisePeerMinPieces(piece + 1)
779         if !cn.peerHasPiece(piece) {
780                 cn.t.incPieceAvailability(piece)
781         }
782         cn._peerPieces.Add(uint32(piece))
783         if cn.t.wantPieceIndex(piece) {
784                 cn.updateRequests("have")
785         }
786         cn.peerPiecesChanged()
787         return nil
788 }
789
790 func (cn *PeerConn) peerSentBitfield(bf []bool) error {
791         if len(bf)%8 != 0 {
792                 panic("expected bitfield length divisible by 8")
793         }
794         // We know that the last byte means that at most the last 7 bits are wasted.
795         cn.raisePeerMinPieces(pieceIndex(len(bf) - 7))
796         if cn.t.haveInfo() && len(bf) > int(cn.t.numPieces()) {
797                 // Ignore known excess pieces.
798                 bf = bf[:cn.t.numPieces()]
799         }
800         bm := boolSliceToBitmap(bf)
801         if cn.t.haveInfo() && pieceIndex(bm.GetCardinality()) == cn.t.numPieces() {
802                 cn.onPeerHasAllPieces()
803                 return nil
804         }
805         if !bm.IsEmpty() {
806                 cn.raisePeerMinPieces(pieceIndex(bm.Maximum()) + 1)
807         }
808         shouldUpdateRequests := false
809         if cn.peerSentHaveAll {
810                 if !cn.t.deleteConnWithAllPieces(&cn.Peer) {
811                         panic(cn)
812                 }
813                 cn.peerSentHaveAll = false
814                 if !cn._peerPieces.IsEmpty() {
815                         panic("if peer has all, we expect no individual peer pieces to be set")
816                 }
817         } else {
818                 bm.Xor(&cn._peerPieces)
819         }
820         cn.peerSentHaveAll = false
821         // bm is now 'on' for pieces that are changing
822         bm.Iterate(func(x uint32) bool {
823                 pi := pieceIndex(x)
824                 if cn._peerPieces.Contains(x) {
825                         // Then we must be losing this piece
826                         cn.t.decPieceAvailability(pi)
827                 } else {
828                         if !shouldUpdateRequests && cn.t.wantPieceIndex(pieceIndex(x)) {
829                                 shouldUpdateRequests = true
830                         }
831                         // We must be gaining this piece
832                         cn.t.incPieceAvailability(pieceIndex(x))
833                 }
834                 return true
835         })
836         // Apply the changes. If we had everything previously, this should be empty, so xor is the same
837         // as or.
838         cn._peerPieces.Xor(&bm)
839         if shouldUpdateRequests {
840                 cn.updateRequests("bitfield")
841         }
842         // We didn't guard this before, I see no reason to do it now.
843         cn.peerPiecesChanged()
844         return nil
845 }
846
847 func (cn *PeerConn) onPeerHasAllPieces() {
848         t := cn.t
849         if t.haveInfo() {
850                 cn._peerPieces.Iterate(func(x uint32) bool {
851                         t.decPieceAvailability(pieceIndex(x))
852                         return true
853                 })
854         }
855         t.addConnWithAllPieces(&cn.Peer)
856         cn.peerSentHaveAll = true
857         cn._peerPieces.Clear()
858         if !cn.t._pendingPieces.IsEmpty() {
859                 cn.updateRequests("Peer.onPeerHasAllPieces")
860         }
861         cn.peerPiecesChanged()
862 }
863
864 func (cn *PeerConn) onPeerSentHaveAll() error {
865         cn.onPeerHasAllPieces()
866         return nil
867 }
868
869 func (cn *PeerConn) peerSentHaveNone() error {
870         if cn.peerSentHaveAll {
871                 cn.t.decPeerPieceAvailability(&cn.Peer)
872         }
873         cn._peerPieces.Clear()
874         cn.peerSentHaveAll = false
875         cn.peerPiecesChanged()
876         return nil
877 }
878
879 func (c *PeerConn) requestPendingMetadata() {
880         if c.t.haveInfo() {
881                 return
882         }
883         if c.PeerExtensionIDs[pp.ExtensionNameMetadata] == 0 {
884                 // Peer doesn't support this.
885                 return
886         }
887         // Request metadata pieces that we don't have in a random order.
888         var pending []int
889         for index := 0; index < c.t.metadataPieceCount(); index++ {
890                 if !c.t.haveMetadataPiece(index) && !c.requestedMetadataPiece(index) {
891                         pending = append(pending, index)
892                 }
893         }
894         rand.Shuffle(len(pending), func(i, j int) { pending[i], pending[j] = pending[j], pending[i] })
895         for _, i := range pending {
896                 c.requestMetadataPiece(i)
897         }
898 }
899
900 func (cn *PeerConn) wroteMsg(msg *pp.Message) {
901         torrent.Add(fmt.Sprintf("messages written of type %s", msg.Type.String()), 1)
902         if msg.Type == pp.Extended {
903                 for name, id := range cn.PeerExtensionIDs {
904                         if id != msg.ExtendedID {
905                                 continue
906                         }
907                         torrent.Add(fmt.Sprintf("Extended messages written for protocol %q", name), 1)
908                 }
909         }
910         cn.allStats(func(cs *ConnStats) { cs.wroteMsg(msg) })
911 }
912
913 // After handshake, we know what Torrent and Client stats to include for a
914 // connection.
915 func (cn *Peer) postHandshakeStats(f func(*ConnStats)) {
916         t := cn.t
917         f(&t.stats)
918         f(&t.cl.stats)
919 }
920
921 // All ConnStats that include this connection. Some objects are not known
922 // until the handshake is complete, after which it's expected to reconcile the
923 // differences.
924 func (cn *Peer) allStats(f func(*ConnStats)) {
925         f(&cn._stats)
926         if cn.reconciledHandshakeStats {
927                 cn.postHandshakeStats(f)
928         }
929 }
930
931 func (cn *PeerConn) wroteBytes(n int64) {
932         cn.allStats(add(n, func(cs *ConnStats) *Count { return &cs.BytesWritten }))
933 }
934
935 func (cn *Peer) readBytes(n int64) {
936         cn.allStats(add(n, func(cs *ConnStats) *Count { return &cs.BytesRead }))
937 }
938
939 // Returns whether the connection could be useful to us. We're seeding and
940 // they want data, we don't have metainfo and they can provide it, etc.
941 func (c *Peer) useful() bool {
942         t := c.t
943         if c.closed.IsSet() {
944                 return false
945         }
946         if !t.haveInfo() {
947                 return c.supportsExtension("ut_metadata")
948         }
949         if t.seeding() && c.peerInterested {
950                 return true
951         }
952         if c.peerHasWantedPieces() {
953                 return true
954         }
955         return false
956 }
957
958 func (c *Peer) lastHelpful() (ret time.Time) {
959         ret = c.lastUsefulChunkReceived
960         if c.t.seeding() && c.lastChunkSent.After(ret) {
961                 ret = c.lastChunkSent
962         }
963         return
964 }
965
966 func (c *PeerConn) fastEnabled() bool {
967         return c.PeerExtensionBytes.SupportsFast() && c.t.cl.config.Extensions.SupportsFast()
968 }
969
970 func (c *PeerConn) reject(r Request) {
971         if !c.fastEnabled() {
972                 panic("fast not enabled")
973         }
974         c.write(r.ToMsg(pp.Reject))
975         delete(c.peerRequests, r)
976 }
977
978 func (c *PeerConn) onReadRequest(r Request) error {
979         requestedChunkLengths.Add(strconv.FormatUint(r.Length.Uint64(), 10), 1)
980         if _, ok := c.peerRequests[r]; ok {
981                 torrent.Add("duplicate requests received", 1)
982                 return nil
983         }
984         if c.choking {
985                 torrent.Add("requests received while choking", 1)
986                 if c.fastEnabled() {
987                         torrent.Add("requests rejected while choking", 1)
988                         c.reject(r)
989                 }
990                 return nil
991         }
992         // TODO: What if they've already requested this?
993         if len(c.peerRequests) >= localClientReqq {
994                 torrent.Add("requests received while queue full", 1)
995                 if c.fastEnabled() {
996                         c.reject(r)
997                 }
998                 // BEP 6 says we may close here if we choose.
999                 return nil
1000         }
1001         if !c.t.havePiece(pieceIndex(r.Index)) {
1002                 // This isn't necessarily them screwing up. We can drop pieces
1003                 // from our storage, and can't communicate this to peers
1004                 // except by reconnecting.
1005                 requestsReceivedForMissingPieces.Add(1)
1006                 return fmt.Errorf("peer requested piece we don't have: %v", r.Index.Int())
1007         }
1008         // Check this after we know we have the piece, so that the piece length will be known.
1009         if r.Begin+r.Length > c.t.pieceLength(pieceIndex(r.Index)) {
1010                 torrent.Add("bad requests received", 1)
1011                 return errors.New("bad Request")
1012         }
1013         if c.peerRequests == nil {
1014                 c.peerRequests = make(map[Request]*peerRequestState, localClientReqq)
1015         }
1016         value := &peerRequestState{}
1017         c.peerRequests[r] = value
1018         go c.peerRequestDataReader(r, value)
1019         // c.tickleWriter()
1020         return nil
1021 }
1022
1023 func (c *PeerConn) peerRequestDataReader(r Request, prs *peerRequestState) {
1024         b, err := readPeerRequestData(r, c)
1025         c.locker().Lock()
1026         defer c.locker().Unlock()
1027         if err != nil {
1028                 c.peerRequestDataReadFailed(err, r)
1029         } else {
1030                 if b == nil {
1031                         panic("data must be non-nil to trigger send")
1032                 }
1033                 torrent.Add("peer request data read successes", 1)
1034                 prs.data = b
1035                 c.tickleWriter()
1036         }
1037 }
1038
1039 // If this is maintained correctly, we might be able to support optional synchronous reading for
1040 // chunk sending, the way it used to work.
1041 func (c *PeerConn) peerRequestDataReadFailed(err error, r Request) {
1042         torrent.Add("peer request data read failures", 1)
1043         logLevel := log.Warning
1044         if c.t.hasStorageCap() {
1045                 // It's expected that pieces might drop. See
1046                 // https://github.com/anacrolix/torrent/issues/702#issuecomment-1000953313.
1047                 logLevel = log.Debug
1048         }
1049         c.logger.WithDefaultLevel(logLevel).Printf("error reading chunk for peer Request %v: %v", r, err)
1050         if c.t.closed.IsSet() {
1051                 return
1052         }
1053         i := pieceIndex(r.Index)
1054         if c.t.pieceComplete(i) {
1055                 // There used to be more code here that just duplicated the following break. Piece
1056                 // completions are currently cached, so I'm not sure how helpful this update is, except to
1057                 // pull any completion changes pushed to the storage backend in failed reads that got us
1058                 // here.
1059                 c.t.updatePieceCompletion(i)
1060         }
1061         // If we failed to send a chunk, choke the peer to ensure they flush all their requests. We've
1062         // probably dropped a piece from storage, but there's no way to communicate this to the peer. If
1063         // they ask for it again, we'll kick them to allow us to send them an updated bitfield on the
1064         // next connect. TODO: Support rejecting here too.
1065         if c.choking {
1066                 c.logger.WithDefaultLevel(log.Warning).Printf("already choking peer, requests might not be rejected correctly")
1067         }
1068         c.choke(c.write)
1069 }
1070
1071 func readPeerRequestData(r Request, c *PeerConn) ([]byte, error) {
1072         b := make([]byte, r.Length)
1073         p := c.t.info.Piece(int(r.Index))
1074         n, err := c.t.readAt(b, p.Offset()+int64(r.Begin))
1075         if n == len(b) {
1076                 if err == io.EOF {
1077                         err = nil
1078                 }
1079         } else {
1080                 if err == nil {
1081                         panic("expected error")
1082                 }
1083         }
1084         return b, err
1085 }
1086
1087 func runSafeExtraneous(f func()) {
1088         if true {
1089                 go f()
1090         } else {
1091                 f()
1092         }
1093 }
1094
1095 func (c *PeerConn) logProtocolBehaviour(level log.Level, format string, arg ...interface{}) {
1096         c.logger.WithLevel(level).WithContextText(fmt.Sprintf(
1097                 "peer id %q, ext v %q", c.PeerID, c.PeerClientName.Load(),
1098         )).SkipCallers(1).Printf(format, arg...)
1099 }
1100
1101 // Processes incoming BitTorrent wire-protocol messages. The client lock is held upon entry and
1102 // exit. Returning will end the connection.
1103 func (c *PeerConn) mainReadLoop() (err error) {
1104         defer func() {
1105                 if err != nil {
1106                         torrent.Add("connection.mainReadLoop returned with error", 1)
1107                 } else {
1108                         torrent.Add("connection.mainReadLoop returned with no error", 1)
1109                 }
1110         }()
1111         t := c.t
1112         cl := t.cl
1113
1114         decoder := pp.Decoder{
1115                 R:         bufio.NewReaderSize(c.r, 1<<17),
1116                 MaxLength: 256 * 1024,
1117                 Pool:      &t.chunkPool,
1118         }
1119         for {
1120                 var msg pp.Message
1121                 func() {
1122                         cl.unlock()
1123                         defer cl.lock()
1124                         err = decoder.Decode(&msg)
1125                 }()
1126                 if cb := c.callbacks.ReadMessage; cb != nil && err == nil {
1127                         cb(c, &msg)
1128                 }
1129                 if t.closed.IsSet() || c.closed.IsSet() {
1130                         return nil
1131                 }
1132                 if err != nil {
1133                         return err
1134                 }
1135                 c.lastMessageReceived = time.Now()
1136                 if msg.Keepalive {
1137                         receivedKeepalives.Add(1)
1138                         continue
1139                 }
1140                 messageTypesReceived.Add(msg.Type.String(), 1)
1141                 if msg.Type.FastExtension() && !c.fastEnabled() {
1142                         runSafeExtraneous(func() { torrent.Add("fast messages received when extension is disabled", 1) })
1143                         return fmt.Errorf("received fast extension message (type=%v) but extension is disabled", msg.Type)
1144                 }
1145                 switch msg.Type {
1146                 case pp.Choke:
1147                         if c.peerChoking {
1148                                 break
1149                         }
1150                         if !c.fastEnabled() {
1151                                 if !c.deleteAllRequests().IsEmpty() {
1152                                         c.t.iterPeers(func(p *Peer) {
1153                                                 if p.isLowOnRequests() {
1154                                                         p.updateRequests("choked by non-fast PeerConn")
1155                                                 }
1156                                         })
1157                                 }
1158                         } else {
1159                                 // We don't decrement pending requests here, let's wait for the peer to either
1160                                 // reject or satisfy the outstanding requests. Additionally, some peers may unchoke
1161                                 // us and resume where they left off, we don't want to have piled on to those chunks
1162                                 // in the meanwhile. I think a peer's ability to abuse this should be limited: they
1163                                 // could let us request a lot of stuff, then choke us and never reject, but they're
1164                                 // only a single peer, our chunk balancing should smooth over this abuse.
1165                         }
1166                         c.peerChoking = true
1167                         c.updateExpectingChunks()
1168                 case pp.Unchoke:
1169                         if !c.peerChoking {
1170                                 // Some clients do this for some reason. Transmission doesn't error on this, so we
1171                                 // won't for consistency.
1172                                 c.logProtocolBehaviour(log.Debug, "received unchoke when already unchoked")
1173                                 break
1174                         }
1175                         c.peerChoking = false
1176                         preservedCount := 0
1177                         c.requestState.Requests.Iterate(func(x uint32) bool {
1178                                 if !c.peerAllowedFast.Contains(x / c.t.chunksPerRegularPiece()) {
1179                                         preservedCount++
1180                                 }
1181                                 return true
1182                         })
1183                         if preservedCount != 0 {
1184                                 // TODO: Yes this is a debug log but I'm not happy with the state of the logging lib
1185                                 // right now.
1186                                 c.logger.WithLevel(log.Debug).Printf(
1187                                         "%v requests were preserved while being choked (fast=%v)",
1188                                         preservedCount,
1189                                         c.fastEnabled())
1190                                 torrent.Add("requestsPreservedThroughChoking", int64(preservedCount))
1191                         }
1192                         if !c.t._pendingPieces.IsEmpty() {
1193                                 c.updateRequests("unchoked")
1194                         }
1195                         c.updateExpectingChunks()
1196                 case pp.Interested:
1197                         c.peerInterested = true
1198                         c.tickleWriter()
1199                 case pp.NotInterested:
1200                         c.peerInterested = false
1201                         // We don't clear their requests since it isn't clear in the spec.
1202                         // We'll probably choke them for this, which will clear them if
1203                         // appropriate, and is clearly specified.
1204                 case pp.Have:
1205                         err = c.peerSentHave(pieceIndex(msg.Index))
1206                 case pp.Bitfield:
1207                         err = c.peerSentBitfield(msg.Bitfield)
1208                 case pp.Request:
1209                         r := newRequestFromMessage(&msg)
1210                         err = c.onReadRequest(r)
1211                 case pp.Piece:
1212                         c.doChunkReadStats(int64(len(msg.Piece)))
1213                         err = c.receiveChunk(&msg)
1214                         if len(msg.Piece) == int(t.chunkSize) {
1215                                 t.chunkPool.Put(&msg.Piece)
1216                         }
1217                         if err != nil {
1218                                 err = fmt.Errorf("receiving chunk: %w", err)
1219                         }
1220                 case pp.Cancel:
1221                         req := newRequestFromMessage(&msg)
1222                         c.onPeerSentCancel(req)
1223                 case pp.Port:
1224                         ipa, ok := tryIpPortFromNetAddr(c.RemoteAddr)
1225                         if !ok {
1226                                 break
1227                         }
1228                         pingAddr := net.UDPAddr{
1229                                 IP:   ipa.IP,
1230                                 Port: ipa.Port,
1231                         }
1232                         if msg.Port != 0 {
1233                                 pingAddr.Port = int(msg.Port)
1234                         }
1235                         cl.eachDhtServer(func(s DhtServer) {
1236                                 go s.Ping(&pingAddr)
1237                         })
1238                 case pp.Suggest:
1239                         torrent.Add("suggests received", 1)
1240                         log.Fmsg("peer suggested piece %d", msg.Index).AddValues(c, msg.Index).SetLevel(log.Debug).Log(c.t.logger)
1241                         c.updateRequests("suggested")
1242                 case pp.HaveAll:
1243                         err = c.onPeerSentHaveAll()
1244                 case pp.HaveNone:
1245                         err = c.peerSentHaveNone()
1246                 case pp.Reject:
1247                         req := newRequestFromMessage(&msg)
1248                         if !c.remoteRejectedRequest(c.t.requestIndexFromRequest(req)) {
1249                                 log.Printf("received invalid reject [request=%v, peer=%v]", req, c)
1250                                 err = fmt.Errorf("received invalid reject [request=%v]", req)
1251                         }
1252                 case pp.AllowedFast:
1253                         torrent.Add("allowed fasts received", 1)
1254                         log.Fmsg("peer allowed fast: %d", msg.Index).AddValues(c).SetLevel(log.Debug).Log(c.t.logger)
1255                         c.updateRequests("PeerConn.mainReadLoop allowed fast")
1256                 case pp.Extended:
1257                         err = c.onReadExtendedMsg(msg.ExtendedID, msg.ExtendedPayload)
1258                 default:
1259                         err = fmt.Errorf("received unknown message type: %#v", msg.Type)
1260                 }
1261                 if err != nil {
1262                         return err
1263                 }
1264         }
1265 }
1266
1267 // Returns true if it was valid to reject the request.
1268 func (c *Peer) remoteRejectedRequest(r RequestIndex) bool {
1269         if c.deleteRequest(r) {
1270                 c.decPeakRequests()
1271         } else if !c.requestState.Cancelled.CheckedRemove(r) {
1272                 return false
1273         }
1274         if c.isLowOnRequests() {
1275                 c.updateRequests("Peer.remoteRejectedRequest")
1276         }
1277         c.decExpectedChunkReceive(r)
1278         return true
1279 }
1280
1281 func (c *Peer) decExpectedChunkReceive(r RequestIndex) {
1282         count := c.validReceiveChunks[r]
1283         if count == 1 {
1284                 delete(c.validReceiveChunks, r)
1285         } else if count > 1 {
1286                 c.validReceiveChunks[r] = count - 1
1287         } else {
1288                 panic(r)
1289         }
1290 }
1291
1292 func (c *PeerConn) onReadExtendedMsg(id pp.ExtensionNumber, payload []byte) (err error) {
1293         defer func() {
1294                 // TODO: Should we still do this?
1295                 if err != nil {
1296                         // These clients use their own extension IDs for outgoing message
1297                         // types, which is incorrect.
1298                         if bytes.HasPrefix(c.PeerID[:], []byte("-SD0100-")) || strings.HasPrefix(string(c.PeerID[:]), "-XL0012-") {
1299                                 err = nil
1300                         }
1301                 }
1302         }()
1303         t := c.t
1304         cl := t.cl
1305         switch id {
1306         case pp.HandshakeExtendedID:
1307                 var d pp.ExtendedHandshakeMessage
1308                 if err := bencode.Unmarshal(payload, &d); err != nil {
1309                         c.logger.Printf("error parsing extended handshake message %q: %s", payload, err)
1310                         return fmt.Errorf("unmarshalling extended handshake payload: %w", err)
1311                 }
1312                 if cb := c.callbacks.ReadExtendedHandshake; cb != nil {
1313                         cb(c, &d)
1314                 }
1315                 // c.logger.WithDefaultLevel(log.Debug).Printf("received extended handshake message:\n%s", spew.Sdump(d))
1316                 if d.Reqq != 0 {
1317                         c.PeerMaxRequests = d.Reqq
1318                 }
1319                 c.PeerClientName.Store(d.V)
1320                 if c.PeerExtensionIDs == nil {
1321                         c.PeerExtensionIDs = make(map[pp.ExtensionName]pp.ExtensionNumber, len(d.M))
1322                 }
1323                 c.PeerListenPort = d.Port
1324                 c.PeerPrefersEncryption = d.Encryption
1325                 for name, id := range d.M {
1326                         if _, ok := c.PeerExtensionIDs[name]; !ok {
1327                                 peersSupportingExtension.Add(
1328                                         // expvar.Var.String must produce valid JSON. "ut_payme\xeet_address" was being
1329                                         // entered here which caused problems later when unmarshalling.
1330                                         strconv.Quote(string(name)),
1331                                         1)
1332                         }
1333                         c.PeerExtensionIDs[name] = id
1334                 }
1335                 if d.MetadataSize != 0 {
1336                         if err = t.setMetadataSize(d.MetadataSize); err != nil {
1337                                 return fmt.Errorf("setting metadata size to %d: %w", d.MetadataSize, err)
1338                         }
1339                 }
1340                 c.requestPendingMetadata()
1341                 if !t.cl.config.DisablePEX {
1342                         t.pex.Add(c) // we learnt enough now
1343                         c.pex.Init(c)
1344                 }
1345                 return nil
1346         case metadataExtendedId:
1347                 err := cl.gotMetadataExtensionMsg(payload, t, c)
1348                 if err != nil {
1349                         return fmt.Errorf("handling metadata extension message: %w", err)
1350                 }
1351                 return nil
1352         case pexExtendedId:
1353                 if !c.pex.IsEnabled() {
1354                         return nil // or hang-up maybe?
1355                 }
1356                 return c.pex.Recv(payload)
1357         default:
1358                 return fmt.Errorf("unexpected extended message ID: %v", id)
1359         }
1360 }
1361
1362 // Set both the Reader and Writer for the connection from a single ReadWriter.
1363 func (cn *PeerConn) setRW(rw io.ReadWriter) {
1364         cn.r = rw
1365         cn.w = rw
1366 }
1367
1368 // Returns the Reader and Writer as a combined ReadWriter.
1369 func (cn *PeerConn) rw() io.ReadWriter {
1370         return struct {
1371                 io.Reader
1372                 io.Writer
1373         }{cn.r, cn.w}
1374 }
1375
1376 func (c *Peer) doChunkReadStats(size int64) {
1377         c.allStats(func(cs *ConnStats) { cs.receivedChunk(size) })
1378 }
1379
1380 // Handle a received chunk from a peer.
1381 func (c *Peer) receiveChunk(msg *pp.Message) error {
1382         chunksReceived.Add("total", 1)
1383
1384         ppReq := newRequestFromMessage(msg)
1385         req := c.t.requestIndexFromRequest(ppReq)
1386
1387         if c.peerChoking {
1388                 chunksReceived.Add("while choked", 1)
1389         }
1390
1391         if c.validReceiveChunks[req] <= 0 {
1392                 chunksReceived.Add("unexpected", 1)
1393                 return errors.New("received unexpected chunk")
1394         }
1395         c.decExpectedChunkReceive(req)
1396
1397         if c.peerChoking && c.peerAllowedFast.Contains(bitmap.BitIndex(ppReq.Index)) {
1398                 chunksReceived.Add("due to allowed fast", 1)
1399         }
1400
1401         // The request needs to be deleted immediately to prevent cancels occurring asynchronously when
1402         // have actually already received the piece, while we have the Client unlocked to write the data
1403         // out.
1404         intended := false
1405         {
1406                 if c.requestState.Requests.Contains(req) {
1407                         for _, f := range c.callbacks.ReceivedRequested {
1408                                 f(PeerMessageEvent{c, msg})
1409                         }
1410                 }
1411                 // Request has been satisfied.
1412                 if c.deleteRequest(req) || c.requestState.Cancelled.CheckedRemove(req) {
1413                         intended = true
1414                         if !c.peerChoking {
1415                                 c._chunksReceivedWhileExpecting++
1416                         }
1417                         if c.isLowOnRequests() {
1418                                 c.updateRequests("Peer.receiveChunk deleted request")
1419                         }
1420                 } else {
1421                         chunksReceived.Add("unintended", 1)
1422                 }
1423         }
1424
1425         t := c.t
1426         cl := t.cl
1427
1428         // Do we actually want this chunk?
1429         if t.haveChunk(ppReq) {
1430                 // panic(fmt.Sprintf("%+v", ppReq))
1431                 chunksReceived.Add("redundant", 1)
1432                 c.allStats(add(1, func(cs *ConnStats) *Count { return &cs.ChunksReadWasted }))
1433                 return nil
1434         }
1435
1436         piece := &t.pieces[ppReq.Index]
1437
1438         c.allStats(add(1, func(cs *ConnStats) *Count { return &cs.ChunksReadUseful }))
1439         c.allStats(add(int64(len(msg.Piece)), func(cs *ConnStats) *Count { return &cs.BytesReadUsefulData }))
1440         if intended {
1441                 c.piecesReceivedSinceLastRequestUpdate++
1442                 c.allStats(add(int64(len(msg.Piece)), func(cs *ConnStats) *Count { return &cs.BytesReadUsefulIntendedData }))
1443         }
1444         for _, f := range c.t.cl.config.Callbacks.ReceivedUsefulData {
1445                 f(ReceivedUsefulDataEvent{c, msg})
1446         }
1447         c.lastUsefulChunkReceived = time.Now()
1448
1449         // Need to record that it hasn't been written yet, before we attempt to do
1450         // anything with it.
1451         piece.incrementPendingWrites()
1452         // Record that we have the chunk, so we aren't trying to download it while
1453         // waiting for it to be written to storage.
1454         piece.unpendChunkIndex(chunkIndexFromChunkSpec(ppReq.ChunkSpec, t.chunkSize))
1455
1456         // Cancel pending requests for this chunk from *other* peers.
1457         if p := t.pendingRequests[req]; p != nil {
1458                 if p == c {
1459                         panic("should not be pending request from conn that just received it")
1460                 }
1461                 p.cancel(req)
1462         }
1463
1464         err := func() error {
1465                 cl.unlock()
1466                 defer cl.lock()
1467                 concurrentChunkWrites.Add(1)
1468                 defer concurrentChunkWrites.Add(-1)
1469                 // Write the chunk out. Note that the upper bound on chunk writing concurrency will be the
1470                 // number of connections. We write inline with receiving the chunk (with this lock dance),
1471                 // because we want to handle errors synchronously and I haven't thought of a nice way to
1472                 // defer any concurrency to the storage and have that notify the client of errors. TODO: Do
1473                 // that instead.
1474                 return t.writeChunk(int(msg.Index), int64(msg.Begin), msg.Piece)
1475         }()
1476
1477         piece.decrementPendingWrites()
1478
1479         if err != nil {
1480                 c.logger.WithDefaultLevel(log.Error).Printf("writing received chunk %v: %v", req, err)
1481                 t.pendRequest(req)
1482                 // Necessary to pass TestReceiveChunkStorageFailureSeederFastExtensionDisabled. I think a
1483                 // request update runs while we're writing the chunk that just failed. Then we never do a
1484                 // fresh update after pending the failed request.
1485                 c.updateRequests("Peer.receiveChunk error writing chunk")
1486                 t.onWriteChunkErr(err)
1487                 return nil
1488         }
1489
1490         c.onDirtiedPiece(pieceIndex(ppReq.Index))
1491
1492         // We need to ensure the piece is only queued once, so only the last chunk writer gets this job.
1493         if t.pieceAllDirty(pieceIndex(ppReq.Index)) && piece.pendingWrites == 0 {
1494                 t.queuePieceCheck(pieceIndex(ppReq.Index))
1495                 // We don't pend all chunks here anymore because we don't want code dependent on the dirty
1496                 // chunk status (such as the haveChunk call above) to have to check all the various other
1497                 // piece states like queued for hash, hashing etc. This does mean that we need to be sure
1498                 // that chunk pieces are pended at an appropriate time later however.
1499         }
1500
1501         cl.event.Broadcast()
1502         // We do this because we've written a chunk, and may change PieceState.Partial.
1503         t.publishPieceChange(pieceIndex(ppReq.Index))
1504
1505         return nil
1506 }
1507
1508 func (c *Peer) onDirtiedPiece(piece pieceIndex) {
1509         if c.peerTouchedPieces == nil {
1510                 c.peerTouchedPieces = make(map[pieceIndex]struct{})
1511         }
1512         c.peerTouchedPieces[piece] = struct{}{}
1513         ds := &c.t.pieces[piece].dirtiers
1514         if *ds == nil {
1515                 *ds = make(map[*Peer]struct{})
1516         }
1517         (*ds)[c] = struct{}{}
1518 }
1519
1520 func (c *PeerConn) uploadAllowed() bool {
1521         if c.t.cl.config.NoUpload {
1522                 return false
1523         }
1524         if c.t.dataUploadDisallowed {
1525                 return false
1526         }
1527         if c.t.seeding() {
1528                 return true
1529         }
1530         if !c.peerHasWantedPieces() {
1531                 return false
1532         }
1533         // Don't upload more than 100 KiB more than we download.
1534         if c._stats.BytesWrittenData.Int64() >= c._stats.BytesReadData.Int64()+100<<10 {
1535                 return false
1536         }
1537         return true
1538 }
1539
1540 func (c *PeerConn) setRetryUploadTimer(delay time.Duration) {
1541         if c.uploadTimer == nil {
1542                 c.uploadTimer = time.AfterFunc(delay, c.tickleWriter)
1543         } else {
1544                 c.uploadTimer.Reset(delay)
1545         }
1546 }
1547
1548 // Also handles choking and unchoking of the remote peer.
1549 func (c *PeerConn) upload(msg func(pp.Message) bool) bool {
1550         // Breaking or completing this loop means we don't want to upload to the
1551         // peer anymore, and we choke them.
1552 another:
1553         for c.uploadAllowed() {
1554                 // We want to upload to the peer.
1555                 if !c.unchoke(msg) {
1556                         return false
1557                 }
1558                 for r, state := range c.peerRequests {
1559                         if state.data == nil {
1560                                 continue
1561                         }
1562                         res := c.t.cl.config.UploadRateLimiter.ReserveN(time.Now(), int(r.Length))
1563                         if !res.OK() {
1564                                 panic(fmt.Sprintf("upload rate limiter burst size < %d", r.Length))
1565                         }
1566                         delay := res.Delay()
1567                         if delay > 0 {
1568                                 res.Cancel()
1569                                 c.setRetryUploadTimer(delay)
1570                                 // Hard to say what to return here.
1571                                 return true
1572                         }
1573                         more := c.sendChunk(r, msg, state)
1574                         delete(c.peerRequests, r)
1575                         if !more {
1576                                 return false
1577                         }
1578                         goto another
1579                 }
1580                 return true
1581         }
1582         return c.choke(msg)
1583 }
1584
1585 func (cn *PeerConn) drop() {
1586         cn.t.dropConnection(cn)
1587 }
1588
1589 func (cn *Peer) netGoodPiecesDirtied() int64 {
1590         return cn._stats.PiecesDirtiedGood.Int64() - cn._stats.PiecesDirtiedBad.Int64()
1591 }
1592
1593 func (c *Peer) peerHasWantedPieces() bool {
1594         if all, _ := c.peerHasAllPieces(); all {
1595                 return !c.t.haveAllPieces() && !c.t._pendingPieces.IsEmpty()
1596         }
1597         if !c.t.haveInfo() {
1598                 return !c.peerPieces().IsEmpty()
1599         }
1600         return c.peerPieces().Intersects(&c.t._pendingPieces)
1601 }
1602
1603 // Returns true if an outstanding request is removed. Cancelled requests should be handled
1604 // separately.
1605 func (c *Peer) deleteRequest(r RequestIndex) bool {
1606         if !c.requestState.Requests.CheckedRemove(r) {
1607                 return false
1608         }
1609         for _, f := range c.callbacks.DeletedRequest {
1610                 f(PeerRequestEvent{c, c.t.requestIndexToRequest(r)})
1611         }
1612         c.updateExpectingChunks()
1613         if c.t.requestingPeer(r) != c {
1614                 panic("only one peer should have a given request at a time")
1615         }
1616         delete(c.t.pendingRequests, r)
1617         delete(c.t.lastRequested, r)
1618         // c.t.iterPeers(func(p *Peer) {
1619         //      if p.isLowOnRequests() {
1620         //              p.updateRequests("Peer.deleteRequest")
1621         //      }
1622         // })
1623         return true
1624 }
1625
1626 func (c *Peer) deleteAllRequests() (deleted *roaring.Bitmap) {
1627         deleted = c.requestState.Requests.Clone()
1628         deleted.Iterate(func(x uint32) bool {
1629                 if !c.deleteRequest(x) {
1630                         panic("request should exist")
1631                 }
1632                 return true
1633         })
1634         c.assertNoRequests()
1635         return
1636 }
1637
1638 func (c *Peer) assertNoRequests() {
1639         if !c.requestState.Requests.IsEmpty() {
1640                 panic(c.requestState.Requests.GetCardinality())
1641         }
1642 }
1643
1644 func (c *Peer) cancelAllRequests() (cancelled *roaring.Bitmap) {
1645         cancelled = c.requestState.Requests.Clone()
1646         cancelled.Iterate(func(x uint32) bool {
1647                 c.cancel(x)
1648                 return true
1649         })
1650         c.assertNoRequests()
1651         return
1652 }
1653
1654 // This is called when something has changed that should wake the writer, such as putting stuff into
1655 // the writeBuffer, or changing some state that the writer can act on.
1656 func (c *PeerConn) tickleWriter() {
1657         c.messageWriter.writeCond.Broadcast()
1658 }
1659
1660 func (c *PeerConn) sendChunk(r Request, msg func(pp.Message) bool, state *peerRequestState) (more bool) {
1661         c.lastChunkSent = time.Now()
1662         return msg(pp.Message{
1663                 Type:  pp.Piece,
1664                 Index: r.Index,
1665                 Begin: r.Begin,
1666                 Piece: state.data,
1667         })
1668 }
1669
1670 func (c *PeerConn) setTorrent(t *Torrent) {
1671         if c.t != nil {
1672                 panic("connection already associated with a torrent")
1673         }
1674         c.t = t
1675         c.logger.WithDefaultLevel(log.Debug).Printf("set torrent=%v", t)
1676         t.reconcileHandshakeStats(c)
1677 }
1678
1679 func (c *Peer) peerPriority() (peerPriority, error) {
1680         return bep40Priority(c.remoteIpPort(), c.t.cl.publicAddr(c.remoteIp()))
1681 }
1682
1683 func (c *Peer) remoteIp() net.IP {
1684         host, _, _ := net.SplitHostPort(c.RemoteAddr.String())
1685         return net.ParseIP(host)
1686 }
1687
1688 func (c *Peer) remoteIpPort() IpPort {
1689         ipa, _ := tryIpPortFromNetAddr(c.RemoteAddr)
1690         return IpPort{ipa.IP, uint16(ipa.Port)}
1691 }
1692
1693 func (c *PeerConn) pexPeerFlags() pp.PexPeerFlags {
1694         f := pp.PexPeerFlags(0)
1695         if c.PeerPrefersEncryption {
1696                 f |= pp.PexPrefersEncryption
1697         }
1698         if c.outgoing {
1699                 f |= pp.PexOutgoingConn
1700         }
1701         if c.utp() {
1702                 f |= pp.PexSupportsUtp
1703         }
1704         return f
1705 }
1706
1707 // This returns the address to use if we want to dial the peer again. It incorporates the peer's
1708 // advertised listen port.
1709 func (c *PeerConn) dialAddr() PeerRemoteAddr {
1710         if !c.outgoing && c.PeerListenPort != 0 {
1711                 switch addr := c.RemoteAddr.(type) {
1712                 case *net.TCPAddr:
1713                         dialAddr := *addr
1714                         dialAddr.Port = c.PeerListenPort
1715                         return &dialAddr
1716                 case *net.UDPAddr:
1717                         dialAddr := *addr
1718                         dialAddr.Port = c.PeerListenPort
1719                         return &dialAddr
1720                 }
1721         }
1722         return c.RemoteAddr
1723 }
1724
1725 func (c *PeerConn) pexEvent(t pexEventType) pexEvent {
1726         f := c.pexPeerFlags()
1727         addr := c.dialAddr()
1728         return pexEvent{t, addr, f, nil}
1729 }
1730
1731 func (c *PeerConn) String() string {
1732         return fmt.Sprintf("%T %p [id=%q, exts=%v, v=%q]", c, c, c.PeerID, c.PeerExtensionBytes, c.PeerClientName.Load())
1733 }
1734
1735 func (c *Peer) trust() connectionTrust {
1736         return connectionTrust{c.trusted, c.netGoodPiecesDirtied()}
1737 }
1738
1739 type connectionTrust struct {
1740         Implicit            bool
1741         NetGoodPiecesDirted int64
1742 }
1743
1744 func (l connectionTrust) Less(r connectionTrust) bool {
1745         return multiless.New().Bool(l.Implicit, r.Implicit).Int64(l.NetGoodPiecesDirted, r.NetGoodPiecesDirted).Less()
1746 }
1747
1748 // Returns the pieces the peer could have based on their claims. If we don't know how many pieces
1749 // are in the torrent, it could be a very large range the peer has sent HaveAll.
1750 func (cn *PeerConn) PeerPieces() *roaring.Bitmap {
1751         cn.locker().RLock()
1752         defer cn.locker().RUnlock()
1753         return cn.newPeerPieces()
1754 }
1755
1756 // Returns a new Bitmap that includes bits for all pieces the peer could have based on their claims.
1757 func (cn *Peer) newPeerPieces() *roaring.Bitmap {
1758         // TODO: Can we use copy on write?
1759         ret := cn.peerPieces().Clone()
1760         if all, _ := cn.peerHasAllPieces(); all {
1761                 if cn.t.haveInfo() {
1762                         ret.AddRange(0, bitmap.BitRange(cn.t.numPieces()))
1763                 } else {
1764                         ret.AddRange(0, bitmap.ToEnd)
1765                 }
1766         }
1767         return ret
1768 }
1769
1770 func (cn *Peer) stats() *ConnStats {
1771         return &cn._stats
1772 }
1773
1774 func (p *Peer) TryAsPeerConn() (*PeerConn, bool) {
1775         pc, ok := p.peerImpl.(*PeerConn)
1776         return pc, ok
1777 }
1778
1779 func (p *Peer) uncancelledRequests() uint64 {
1780         return p.requestState.Requests.GetCardinality()
1781 }
1782
1783 func (pc *PeerConn) remoteIsTransmission() bool {
1784         return bytes.HasPrefix(pc.PeerID[:], []byte("-TR")) && pc.PeerID[7] == '-'
1785 }