From 91626883700bb8c4cc1a97b083cb26c44a1390a1 Mon Sep 17 00:00:00 2001 From: Dirk McCormick Date: Mon, 30 Mar 2020 15:54:14 -0400 Subject: [PATCH 1/3] chore: output debug info to track down wantlist leak --- internal/session/session.go | 21 +++++++++++++++++++++ internal/wantmanager/wantmanager.go | 10 ++++++++++ 2 files changed, 31 insertions(+) diff --git a/internal/session/session.go b/internal/session/session.go index 34a7375c..d18c3d11 100644 --- a/internal/session/session.go +++ b/internal/session/session.go @@ -21,6 +21,8 @@ import ( var log = logging.Logger("bs:sess") var sflog = log.Desugar() +var speclog = logging.Logger("bs:special") + const ( broadcastLiveWantsLimit = 64 ) @@ -161,6 +163,8 @@ func New(ctx context.Context, } s.sws = newSessionWantSender(id, pm, sprm, bpm, s.onWantsSent, s.onPeersExhausted) + speclog.Warnf("session %d: ", id) + go s.run(ctx) return s @@ -250,6 +254,13 @@ func (s *Session) SetBaseTickDelay(baseTickDelay time.Duration) { // onWantsSent is called when wants are sent to a peer by the session wants sender func (s *Session) onWantsSent(p peer.ID, wantBlocks []cid.Cid, wantHaves []cid.Cid) { + for _, wb := range wantBlocks { + speclog.Warnf("session %d: sent want-block %s", s.id, wb) + } + for _, wh := range wantHaves { + speclog.Warnf("session %d: sent want-have %s", s.id, wh) + } + allBlks := append(wantBlocks[:len(wantBlocks):len(wantBlocks)], wantHaves...) s.nonBlockingEnqueue(op{op: opWantsSent, keys: allBlks}) } @@ -328,12 +339,17 @@ func (s *Session) run(ctx context.Context) { func (s *Session) broadcastWantHaves(ctx context.Context, wants []cid.Cid) { // If this broadcast is because of an idle timeout (we haven't received // any blocks for a while) then broadcast all pending wants + dbg := "" if wants == nil { + dbg = " (idle tick)" wants = s.sw.PrepareBroadcast() } // Broadcast a want-have for the live wants to everyone we're connected to s.wm.BroadcastWantHaves(ctx, s.id, wants) + for _, w := range wants { + speclog.Warnf("session %d: broadcast%s %s", s.id, dbg, w) + } // do not find providers on consecutive ticks // -- just rely on periodic search widening @@ -365,6 +381,7 @@ func (s *Session) handlePeriodicSearch(ctx context.Context) { s.findMorePeers(ctx, randomWant) s.wm.BroadcastWantHaves(ctx, s.id, []cid.Cid{randomWant}) + speclog.Warnf("session %d: broadcast random want %s (periodic search)", s.id, randomWant) s.periodicSearchTimer.Reset(s.periodicSearchDelay.NextWaitTime()) } @@ -392,6 +409,7 @@ func (s *Session) handleShutdown() { s.sws.Shutdown() // Remove the session from the want manager s.wm.RemoveSession(s.ctx, s.id) + speclog.Warnf("session %d: ", s.id) } // handleReceive is called when the session receives blocks from a peer @@ -441,6 +459,9 @@ func (s *Session) wantBlocks(ctx context.Context, newks []cid.Cid) { if len(ks) > 0 { log.Infof("Ses%d: No peers - broadcasting %d want HAVE requests\n", s.id, len(ks)) s.wm.BroadcastWantHaves(ctx, s.id, ks) + for _, w := range ks { + speclog.Warnf("session %d: initial broadcast %s", s.id, w) + } } } diff --git a/internal/wantmanager/wantmanager.go b/internal/wantmanager/wantmanager.go index 908f9dca..643bc214 100644 --- a/internal/wantmanager/wantmanager.go +++ b/internal/wantmanager/wantmanager.go @@ -73,6 +73,10 @@ func (wm *WantManager) ReceiveFrom(ctx context.Context, p peer.ID, blks []cid.Ci wm.bcwl.RemoveKeys(blks) // Send CANCEL to all peers with want-have / want-block wm.peerHandler.SendCancels(ctx, blks) + + for _, k := range blks { + speclog.Warnf("block recvd: send cancel %s", k) + } } // BroadcastWantHaves is called when want-haves should be broadcast to all @@ -87,6 +91,8 @@ func (wm *WantManager) BroadcastWantHaves(ctx context.Context, ses uint64, wantH wm.peerHandler.BroadcastWantHaves(ctx, wantHaves) } +var speclog = logging.Logger("bs:special") + // RemoveSession is called when the session is shut down func (wm *WantManager) RemoveSession(ctx context.Context, ses uint64) { // Remove session's interest in the given blocks. @@ -101,6 +107,10 @@ func (wm *WantManager) RemoveSession(ctx context.Context, ses uint64) { // Send CANCEL to all peers for blocks that no session is interested in anymore wm.peerHandler.SendCancels(ctx, cancelKs) + + for _, k := range cancelKs { + speclog.Warnf("session %d: (shutdown) send cancel %s", ses, k) + } } // Connected is called when a new peer connects From 1de55c10fffe9a161c623daf8de0d75829f63e1b Mon Sep 17 00:00:00 2001 From: Dirk McCormick Date: Tue, 31 Mar 2020 18:18:46 -0400 Subject: [PATCH 2/3] fix: set bs:special log level to warn --- internal/session/session.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/internal/session/session.go b/internal/session/session.go index d18c3d11..3520934d 100644 --- a/internal/session/session.go +++ b/internal/session/session.go @@ -23,6 +23,10 @@ var sflog = log.Desugar() var speclog = logging.Logger("bs:special") +func init() { + logging.SetLogLevel("bs:special", "warn") +} + const ( broadcastLiveWantsLimit = 64 ) From 797782171d37541db6cc25f8c8eb6dccbe8e0741 Mon Sep 17 00:00:00 2001 From: Dirk McCormick Date: Thu, 2 Apr 2020 15:23:29 -0400 Subject: [PATCH 3/3] fix: add special logger to file --- internal/lu/lu.go | 44 +++++++++++++++++++++++++++++ internal/session/session.go | 7 ++--- internal/wantmanager/wantmanager.go | 3 +- 3 files changed, 48 insertions(+), 6 deletions(-) create mode 100644 internal/lu/lu.go diff --git a/internal/lu/lu.go b/internal/lu/lu.go new file mode 100644 index 00000000..c3b658c2 --- /dev/null +++ b/internal/lu/lu.go @@ -0,0 +1,44 @@ +package lu + +import ( + "fmt" + "os" + "path/filepath" + + logging "github.com/ipfs/go-log" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +var log = logging.Logger("bs:sess") +var sflog = log.Desugar() + +var speclog *zap.SugaredLogger + +func init() { + zapCfg := zap.NewProductionConfig() + zapCfg.Encoding = "console" + zapCfg.EncoderConfig.EncodeLevel = zapcore.CapitalLevelEncoder + zapCfg.Sampling = nil + zapCfg.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + + if logfp := os.Getenv("BS_SPECIAL_LOG_FILE"); len(logfp) > 0 { + if path, err := filepath.Abs(logfp); err != nil { + fmt.Fprintf(os.Stderr, "failed to resolve log path '%q': %s\n", logfp, err) + } else { + zapCfg.OutputPaths = []string{path} + } + } + + cfg := zap.Config(zapCfg) + cfg.Level = zap.NewAtomicLevelAt(zapcore.DebugLevel) + newlog, err := cfg.Build() + if err != nil { + panic(err) + } + speclog = newlog.Named("bs:special").Sugar() +} + +func GetSpecialLogger() *zap.SugaredLogger { + return speclog +} diff --git a/internal/session/session.go b/internal/session/session.go index 3520934d..9779e29c 100644 --- a/internal/session/session.go +++ b/internal/session/session.go @@ -6,6 +6,7 @@ import ( bsbpm "github.com/ipfs/go-bitswap/internal/blockpresencemanager" bsgetter "github.com/ipfs/go-bitswap/internal/getter" + lu "github.com/ipfs/go-bitswap/internal/lu" notifications "github.com/ipfs/go-bitswap/internal/notifications" bspm "github.com/ipfs/go-bitswap/internal/peermanager" bssim "github.com/ipfs/go-bitswap/internal/sessioninterestmanager" @@ -21,11 +22,7 @@ import ( var log = logging.Logger("bs:sess") var sflog = log.Desugar() -var speclog = logging.Logger("bs:special") - -func init() { - logging.SetLogLevel("bs:special", "warn") -} +var speclog = lu.GetSpecialLogger() const ( broadcastLiveWantsLimit = 64 diff --git a/internal/wantmanager/wantmanager.go b/internal/wantmanager/wantmanager.go index 643bc214..3dea5eed 100644 --- a/internal/wantmanager/wantmanager.go +++ b/internal/wantmanager/wantmanager.go @@ -4,6 +4,7 @@ import ( "context" bsbpm "github.com/ipfs/go-bitswap/internal/blockpresencemanager" + lu "github.com/ipfs/go-bitswap/internal/lu" bssim "github.com/ipfs/go-bitswap/internal/sessioninterestmanager" "github.com/ipfs/go-bitswap/internal/sessionmanager" bsswl "github.com/ipfs/go-bitswap/internal/sessionwantlist" @@ -91,7 +92,7 @@ func (wm *WantManager) BroadcastWantHaves(ctx context.Context, ses uint64, wantH wm.peerHandler.BroadcastWantHaves(ctx, wantHaves) } -var speclog = logging.Logger("bs:special") +var speclog = lu.GetSpecialLogger() // RemoveSession is called when the session is shut down func (wm *WantManager) RemoveSession(ctx context.Context, ses uint64) {