From: Matt Joiner Date: Tue, 13 Aug 2024 01:09:34 +0000 (+1000) Subject: Tidy up cmd/torrent cleanup and websocket trackers logging X-Git-Tag: v1.57.0~12 X-Git-Url: http://www.git.stargrave.org/?a=commitdiff_plain;h=f4711825e84e3c24fa96d127098ed5933235029d;p=btrtrc.git Tidy up cmd/torrent cleanup and websocket trackers logging --- diff --git a/client.go b/client.go index 414a3dfd..31a6d88c 100644 --- a/client.go +++ b/client.go @@ -316,7 +316,7 @@ func NewClient(cfg *ClientConfig) (cl *Client, err error) { cl.websocketTrackers = websocketTrackers{ PeerId: cl.peerID, - Logger: cl.logger, + Logger: cl.logger.WithNames("websocketTrackers"), GetAnnounceRequest: func( event tracker.AnnounceEvent, infoHash [20]byte, ) ( diff --git a/cmd/torrent/download.go b/cmd/torrent/download.go index 60482018..9bc16c15 100644 --- a/cmd/torrent/download.go +++ b/cmd/torrent/download.go @@ -405,7 +405,7 @@ func downloadErr(flags downloadFlags) error { <-ctx.Done() } } - spew.Dump(expvar.Get("torrent").(*expvar.Map).Get("chunks received")) + fmt.Printf("chunks received: %v\n", &torrent.ChunksReceived) spew.Dump(client.ConnStats()) clStats := client.ConnStats() sentOverhead := clStats.BytesWritten.Int64() - clStats.BytesWrittenData.Int64() diff --git a/cmd/torrent/main.go b/cmd/torrent/main.go index 2c1081bb..a15351b9 100644 --- a/cmd/torrent/main.go +++ b/cmd/torrent/main.go @@ -5,6 +5,7 @@ import ( "context" "encoding/json" "fmt" + app "github.com/anacrolix/gostdapp" "io" stdLog "log" "net/http" @@ -39,12 +40,15 @@ func shutdownTracerProvider(ctx context.Context, tp *trace.TracerProvider) { } func main() { + app.RunContext(mainErr) +} + +func mainErr(ctx context.Context) error { defer stdLog.SetFlags(stdLog.Flags() | stdLog.Lshortfile) - ctx := context.Background() tracingExporter, err := otlptracegrpc.New(ctx) if err != nil { - log.Fatalf("creating tracing exporter: %v", err) + return fmt.Errorf("creating tracing exporter: %w", err) } tracerProvider := trace.NewTracerProvider(trace.WithBatcher(tracingExporter)) defer shutdownTracerProvider(ctx, tracerProvider) @@ -148,5 +152,8 @@ func main() { bargle.Subcommand{Name: "serve", Command: serve()}, bargle.Subcommand{Name: "create", Command: create()}, ) + // Well this sux, this old version of bargle doesn't return so we can let the gostdapp Context + // clean up. main.Run() + return nil } diff --git a/global.go b/global.go index 585bbeaf..c44dfb37 100644 --- a/global.go +++ b/global.go @@ -25,7 +25,7 @@ func defaultPeerExtensionBytes() PeerExtensionBits { func init() { torrent.Set("peers supporting extension", &peersSupportingExtension) - torrent.Set("chunks received", &chunksReceived) + torrent.Set("chunks received", &ChunksReceived) } // I could move a lot of these counters to their own file, but I suspect they @@ -33,7 +33,9 @@ func init() { var ( torrent = expvar.NewMap("torrent") peersSupportingExtension expvar.Map - chunksReceived expvar.Map + // This could move at any time. It contains counts of chunks received and the conditions they + // were received. + ChunksReceived expvar.Map pieceHashedCorrect = expvar.NewInt("pieceHashedCorrect") pieceHashedNotCorrect = expvar.NewInt("pieceHashedNotCorrect") diff --git a/go.sum b/go.sum index 14210a02..ae5edd04 100644 --- a/go.sum +++ b/go.sum @@ -66,8 +66,6 @@ github.com/alexflint/go-scalar v1.1.0 h1:aaAouLLzI9TChcPXotr6gUhq+Scr8rl0P9P4Pnl github.com/alexflint/go-scalar v1.1.0/go.mod h1:LoFvNMqS1CPrMVltza4LvnGKhaSpc3oyLEBUZVhhS2o= github.com/anacrolix/backtrace v0.0.0-20221205112523-22a61db8f82e h1:A0Ty9UeyBDIo29ZMnk0AvPqWDIa4HVvCaJqWNlCrMXA= github.com/anacrolix/backtrace v0.0.0-20221205112523-22a61db8f82e/go.mod h1:4YFqy+788tLJWtin2jNliYVJi+8aDejG9zcu/2/pONw= -github.com/anacrolix/bargle v0.0.0-20220630015206-d7a4d433886a h1:KCP9QvHlLoUQBOaTf/YCuOzG91Ym1cPB6S68O4Q3puo= -github.com/anacrolix/bargle v0.0.0-20220630015206-d7a4d433886a/go.mod h1:9xUiZbkh+94FbiIAL1HXpAIBa832f3Mp07rRPl5c5RQ= github.com/anacrolix/bargle v0.0.0-20221014000746-4f2739072e9d h1:ypNOsIwvdumNRlqWj/hsnLs5TyQWQOylwi+T9Qs454A= github.com/anacrolix/bargle v0.0.0-20221014000746-4f2739072e9d/go.mod h1:9xUiZbkh+94FbiIAL1HXpAIBa832f3Mp07rRPl5c5RQ= github.com/anacrolix/chansync v0.4.1-0.20240627045151-1aa1ac392fe8 h1:eyb0bBaQKMOh5Se/Qg54shijc8K4zpQiOjEhKFADkQM= diff --git a/peer.go b/peer.go index 55e8f19f..e28b5afd 100644 --- a/peer.go +++ b/peer.go @@ -608,7 +608,7 @@ func (c *Peer) doChunkReadStats(size int64) { // Handle a received chunk from a peer. func (c *Peer) receiveChunk(msg *pp.Message) error { - chunksReceived.Add("total", 1) + ChunksReceived.Add("total", 1) ppReq := newRequestFromMessage(msg) t := c.t @@ -628,17 +628,17 @@ func (c *Peer) receiveChunk(msg *pp.Message) error { defer recordBlockForSmartBan() if c.peerChoking { - chunksReceived.Add("while choked", 1) + ChunksReceived.Add("while choked", 1) } if c.validReceiveChunks[req] <= 0 { - chunksReceived.Add("unexpected", 1) + ChunksReceived.Add("unexpected", 1) return errors.New("received unexpected chunk") } c.decExpectedChunkReceive(req) if c.peerChoking && c.peerAllowedFast.Contains(pieceIndex(ppReq.Index)) { - chunksReceived.Add("due to allowed fast", 1) + ChunksReceived.Add("due to allowed fast", 1) } // The request needs to be deleted immediately to prevent cancels occurring asynchronously when @@ -661,7 +661,7 @@ func (c *Peer) receiveChunk(msg *pp.Message) error { c.updateRequests("Peer.receiveChunk deleted request") } } else { - chunksReceived.Add("unintended", 1) + ChunksReceived.Add("unintended", 1) } } @@ -670,7 +670,7 @@ func (c *Peer) receiveChunk(msg *pp.Message) error { // Do we actually want this chunk? if t.haveChunk(ppReq) { // panic(fmt.Sprintf("%+v", ppReq)) - chunksReceived.Add("redundant", 1) + ChunksReceived.Add("redundant", 1) c.allStats(add(1, func(cs *ConnStats) *Count { return &cs.ChunksReadWasted })) return nil } diff --git a/torrent.go b/torrent.go index 28bda274..2742ad6a 100644 --- a/torrent.go +++ b/torrent.go @@ -1910,10 +1910,11 @@ func (t *Torrent) startWebsocketAnnouncer(u url.URL, shortInfohash [20]byte) tor go func() { err := wtc.Announce(tracker.Started, shortInfohash) if err != nil { - t.logger.WithDefaultLevel(log.Warning).Printf( - "error in initial announce to %q: %v", - u.String(), err, - ) + level := log.Warning + if t.closed.IsSet() { + level = log.Debug + } + t.logger.Levelf(level, "error doing initial announce to %q: %v", u.String(), err) } }() return wst diff --git a/webtorrent/tracker-client.go b/webtorrent/tracker-client.go index 09ea652f..8b307c7b 100644 --- a/webtorrent/tracker-client.go +++ b/webtorrent/tracker-client.go @@ -234,6 +234,7 @@ func (tc *TrackerClient) Announce(event tracker.AnnounceEvent, infoHash [20]byte return fmt.Errorf("creating offer: %w", err) } + tc.Logger.Levelf(log.Debug, "announcing offer") err = tc.announce(event, infoHash, []outboundOffer{ { offerId: offerIDBinary, @@ -308,7 +309,7 @@ func (tc *TrackerClient) trackerReadLoop(tracker *websocket.Conn) error { if err != nil { return fmt.Errorf("read message error: %w", err) } - // tc.Logger.WithDefaultLevel(log.Debug).Printf("received message from tracker: %q", message) + tc.Logger.Levelf(log.Debug, "received message: %q", message) var ar AnnounceResponse if err := json.Unmarshal(message, &ar); err != nil { @@ -333,7 +334,13 @@ func (tc *TrackerClient) trackerReadLoop(tracker *websocket.Conn) error { case ar.Answer != nil: tc.handleAnswer(ar.OfferID, *ar.Answer) default: - tc.Logger.Levelf(log.Warning, "unhandled announce response %q", message) + // wss://tracker.openwebtorrent.com appears to respond to an initial announces without + // an offer or answer. I think that's fine. Let's check it at least contains an + // infohash. + _, err := jsonStringToInfoHash(ar.InfoHash) + if err != nil { + tc.Logger.Levelf(log.Warning, "unexpected announce response %q", message) + } } } } diff --git a/webtorrent/transport.go b/webtorrent/transport.go index a8b6a845..75f13762 100644 --- a/webtorrent/transport.go +++ b/webtorrent/transport.go @@ -70,7 +70,7 @@ func newPeerConnection(logger log.Logger, iceServers []webrtc.ICEServer) (*wrapp } // If the state change handler intends to call Close, it should call it on the wrapper. wpc.OnConnectionStateChange(func(state webrtc.PeerConnectionState) { - logger.Levelf(log.Warning, "webrtc PeerConnection state changed to %v", state) + logger.Levelf(log.Debug, "webrtc PeerConnection state changed to %v", state) span.AddEvent("connection state changed", trace.WithAttributes(attribute.String("state", state.String()))) }) return wpc, nil diff --git a/wstracker.go b/wstracker.go index f94c3923..8952cc94 100644 --- a/wstracker.go +++ b/wstracker.go @@ -57,7 +57,11 @@ func (me *websocketTrackers) Get(url string, infoHash [20]byte) (*webtorrent.Tra defer me.mu.Unlock() value, ok := me.clients[url] if !ok { - dialer := &websocket.Dialer{Proxy: me.Proxy, NetDialContext: me.DialContext, HandshakeTimeout: websocket.DefaultDialer.HandshakeTimeout} + dialer := &websocket.Dialer{ + Proxy: me.Proxy, + NetDialContext: me.DialContext, + HandshakeTimeout: websocket.DefaultDialer.HandshakeTimeout, + } value = &refCountedWebtorrentTrackerClient{ TrackerClient: webtorrent.TrackerClient{ Dialer: dialer, @@ -65,9 +69,11 @@ func (me *websocketTrackers) Get(url string, infoHash [20]byte) (*webtorrent.Tra GetAnnounceRequest: me.GetAnnounceRequest, PeerId: me.PeerId, OnConn: me.OnConn, - Logger: me.Logger.WithText(func(m log.Msg) string { - return fmt.Sprintf("tracker client for %q: %v", url, m) - }), + Logger: me.Logger.WithText( + func(m log.Msg) string { + return fmt.Sprintf("tracker client for %q: %v", url, m) + }, + ), WebsocketTrackerHttpHeader: me.WebsocketTrackerHttpHeader, ICEServers: me.ICEServers, },