From 7719da79afb9dd46ff962eae1397bc11484a8afd Mon Sep 17 00:00:00 2001 From: Marcin Rataj Date: Fri, 6 Jun 2025 16:36:24 +0200 Subject: [PATCH 1/4] chore(provider): meaningful info level log arguably, these are not low-level details from DEBUG level of individual CIDs, but high level start/stop of reprovide event --- provider/reprovider.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/provider/reprovider.go b/provider/reprovider.go index 3fca9292c..3660ebe9a 100644 --- a/provider/reprovider.go +++ b/provider/reprovider.go @@ -367,7 +367,7 @@ func (s *reprovider) waitUntilProvideSystemReady() { ticker = time.NewTicker(time.Minute) defer ticker.Stop() } - log.Debugf("reprovider system not ready") + log.Infof("reprovider system not ready, waiting 1m") select { case <-ticker.C: case <-s.ctx.Done(): @@ -454,16 +454,16 @@ func (s *reprovider) Reprovide(ctx context.Context) error { s.waitUntilProvideSystemReady() - log.Debugf("starting reprovide of %d keys", len(keys)) + log.Infof("starting reprovide of %d keys", len(keys)) start := time.Now() err := doProvideMany(s.ctx, s.rsys, keys) if err != nil { - log.Debugf("reproviding failed %v", err) + log.Infof("reproviding failed %v", err) continue } dur := time.Since(start) recentAvgProvideDuration := dur / time.Duration(len(keys)) - log.Debugf("finished reproviding %d keys. It took %v with an average of %v per provide", len(keys), dur, recentAvgProvideDuration) + log.Infof("finished reproviding %d keys. It took %v with an average of %v per provide", len(keys), dur, recentAvgProvideDuration) totalProvideTime := time.Duration(s.totalReprovides) * s.avgReprovideDuration s.statLk.Lock() From 58eb3c26f48dae02818443adf7b6c26a74bba9a1 Mon Sep 17 00:00:00 2001 From: Hector Sanjuan Date: Fri, 13 Jun 2025 12:55:44 +0200 Subject: [PATCH 2/4] chore(provider): some more debug logging --- provider/reprovider.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/provider/reprovider.go b/provider/reprovider.go index 3660ebe9a..77f0a3638 100644 --- a/provider/reprovider.go +++ b/provider/reprovider.go @@ -263,6 +263,7 @@ func (s *reprovider) provideWorker() { provCh := s.q.Dequeue() provideFunc := func(ctx context.Context, c cid.Cid) { + log.Debugf("provider worker: providing %s", c) if err := s.rsys.Provide(ctx, c, true); err != nil { log.Errorf("failed to provide %s: %s", c, err) } @@ -458,7 +459,7 @@ func (s *reprovider) Reprovide(ctx context.Context) error { start := time.Now() err := doProvideMany(s.ctx, s.rsys, keys) if err != nil { - log.Infof("reproviding failed %v", err) + log.Warnf("reproviding failed %v", err) continue } dur := time.Since(start) @@ -539,6 +540,7 @@ func doProvideMany(ctx context.Context, r Provide, keys []multihash.Multihash) e } for _, k := range keys { + log.Debugf("providing %s", k) if err := r.Provide(ctx, cid.NewCidV1(cid.Raw, k), true); err != nil { return err } From 2e3aea6ced3b1df560c9af55209ffa1b829aa42c Mon Sep 17 00:00:00 2001 From: Hector Sanjuan Date: Fri, 13 Jun 2025 12:59:54 +0200 Subject: [PATCH 3/4] provider: consolidate logs into "provider" facility --- CHANGELOG.md | 2 ++ provider/internal/queue/queue.go | 14 +++++++------- provider/provider.go | 9 +++------ provider/reprovider.go | 2 +- 4 files changed, 13 insertions(+), 14 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c25117d01..8b8f6f7db 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,8 @@ The following emojis are used to highlight certain changes: ### Changed +- `provider`: previously, the code in this module was logging to `reprovider.simple`, `provider.batched` and `provider.queue` facilities. They have now been consolidated in a single `provider` logging facility, along with some adjustments to logging levels and extra debug statements. + ### Removed - `bitswap/server` do not allow override of peer ledger with `WithPeerLedger` [#938](https://github.com/ipfs/boxo/pull/938) diff --git a/provider/internal/queue/queue.go b/provider/internal/queue/queue.go index fbda5d7c4..4049640af 100644 --- a/provider/internal/queue/queue.go +++ b/provider/internal/queue/queue.go @@ -17,7 +17,7 @@ import ( logging "github.com/ipfs/go-log/v2" ) -var log = logging.Logger("provider.queue") +var log = logging.Logger("provider") const ( // batchSize is the limit on number of CIDs kept in memory at which ther @@ -142,7 +142,7 @@ func (q *Queue) worker(ctx context.Context) { defer func() { if c != cid.Undef { if err := q.ds.Put(ctx, k, c.Bytes()); err != nil { - log.Errorw("Failed to write cid to datastore", "err", err) + log.Errorw("provider queue: failed to write cid to datastore", "err", err) } counter++ } @@ -174,18 +174,18 @@ func (q *Queue) worker(ctx context.Context) { if !dsEmpty { head, err := q.getQueueHead(ctx) if err != nil { - log.Errorw("Error querying for head of queue, stopping provider", "err", err) + log.Errorw("provider queue: error querying for head of queue, stopping provider", "err", err) return } if head != nil { k = datastore.NewKey(head.Key) if err = q.ds.Delete(ctx, k); err != nil { - log.Errorw("Error deleting queue entry, stopping provider", "err", err, "key", head.Key) + log.Errorw("provider queue: error deleting queue entry, stopping provider", "err", err, "key", head.Key) return } c, err = cid.Parse(head.Value) if err != nil { - log.Warnw("Error parsing queue entry cid, removing it from queue", "err", err, "key", head.Key) + log.Warnw("provider queue: error parsing queue entry cid, removing it from queue", "err", err, "key", head.Key) continue } } else { @@ -257,7 +257,7 @@ func (q *Queue) worker(ctx context.Context) { err = q.commitInput(ctx, counter, &inBuf) if err != nil { if !errors.Is(err, context.Canceled) { - log.Errorw("Error writing CIDs to datastore, stopping provider", "err", err) + log.Errorw("provider queue: error writing CIDs to datastore, stopping provider", "err", err) } return } @@ -296,7 +296,7 @@ func (q *Queue) commitInput(ctx context.Context, counter uint64, cids *deque.Deq c := cids.At(i) key := datastore.NewKey(fmt.Sprintf("%020d/%s", counter, cstr)) if err = b.Put(ctx, key, c.Bytes()); err != nil { - log.Errorw("Failed to add cid to batch", "err", err) + log.Errorw("provider queue: failed to add cid to batch", "err", err) continue } counter++ diff --git a/provider/provider.go b/provider/provider.go index 485a3ff4c..c9b3b3dec 100644 --- a/provider/provider.go +++ b/provider/provider.go @@ -16,12 +16,9 @@ import ( pin "github.com/ipfs/boxo/pinning/pinner" "github.com/ipfs/go-cid" "github.com/ipfs/go-cidutil" - logging "github.com/ipfs/go-log/v2" cidlink "github.com/ipld/go-ipld-prime/linking/cid" ) -var logR = logging.Logger("reprovider.simple") - // Provider announces blocks to the network type Provider interface { // Provide takes a cid and makes an attempt to announce it to the network @@ -107,7 +104,7 @@ func pinSet(ctx context.Context, pinning pin.Pinner, fetchConfig fetcher.Factory // 1. Recursive keys for sc := range pinning.RecursiveKeys(ctx, false) { if sc.Err != nil { - logR.Errorf("reprovide recursive pins: %s", sc.Err) + log.Errorf("reprovide recursive pins: %s", sc.Err) return } if !onlyRoots { @@ -120,7 +117,7 @@ func pinSet(ctx context.Context, pinning pin.Pinner, fetchConfig fetcher.Factory // 2. Direct pins for sc := range pinning.DirectKeys(ctx, false) { if sc.Err != nil { - logR.Errorf("reprovide direct pins: %s", sc.Err) + log.Errorf("reprovide direct pins: %s", sc.Err) return } _ = set.Visitor(ctx)(sc.Pin.Key) @@ -143,7 +140,7 @@ func pinSet(ctx context.Context, pinning pin.Pinner, fetchConfig fetcher.Factory }) }) if err != nil { - logR.Errorf("reprovide indirect pins: %s", err) + log.Errorf("reprovide indirect pins: %s", err) return } }() diff --git a/provider/reprovider.go b/provider/reprovider.go index 77f0a3638..77a5d4df2 100644 --- a/provider/reprovider.go +++ b/provider/reprovider.go @@ -38,7 +38,7 @@ const ( provideDelayWarnDuration = 15 * time.Second ) -var log = logging.Logger("provider.batched") +var log = logging.Logger("provider") type reprovider struct { ctx context.Context From 6cd7e50ea608d980f4ddef5cd55f5020bc9f5591 Mon Sep 17 00:00:00 2001 From: Hector Sanjuan Date: Fri, 13 Jun 2025 13:04:05 +0200 Subject: [PATCH 4/4] chore(provider): raise error to error log level --- provider/reprovider.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/provider/reprovider.go b/provider/reprovider.go index 77a5d4df2..21b18d38d 100644 --- a/provider/reprovider.go +++ b/provider/reprovider.go @@ -459,7 +459,7 @@ func (s *reprovider) Reprovide(ctx context.Context) error { start := time.Now() err := doProvideMany(s.ctx, s.rsys, keys) if err != nil { - log.Warnf("reproviding failed %v", err) + log.Errorf("reproviding failed %v", err) continue } dur := time.Since(start)