@cryptotaxi247 / kubo / commits / 605974351

fix(log): scope provide logs to "provider" subsystem (#11289)

Provide/reprovide messages from core/node/provider.go were emitted under core:constructor (the shared core/node constructor subsystem), making GOLOG_LOG_LEVEL and `ipfs log level` hard to target for provide visibility. Scope them to "provider", matching boxo's provider package so a single lever covers both layers. - core/node/provider.go: new providerLog at the "provider" subsystem, applied to 25 keystore/reprovide/strategy/throughput call sites - test/cli/provider_test.go: reprovide dedup subtest raises provider=info instead of core:constructor=info - docs/debug-guide.md: new "Known logger subsystems" section listing provider, dht/provider, dht/provider/lan, dsqueue - docs/environment-variables.md: link to the new section from under GOLOG_LOG_LEVEL

Marcin Rataj committed Apr 23, 2026 at 00:15 UTC 6059743518973c19322f8867af1b7b5c323b21c9

4 files changed +53 -26

core/node/provider.go

+32 -25

@@ -70,6 +70,13 @@ var (

70 keystoreDatastoreKey = datastore.NewKey("keystore")

71 )

73 +// providerLog is the go-log subsystem used for provide/reprovide-related

74 +// messages emitted from kubo's own orchestration code. It shares the

75 +// "provider" subsystem name with boxo's provider package so users can set

76 +// GOLOG_LOG_LEVEL=provider=<level> to control both layers at once. See

77 +// docs/debug-guide.md for the full list of provide-related subsystems.

78 +var providerLog = log.Logger("provider")

79 +

80 var errAcceleratedDHTNotReady = errors.New("AcceleratedDHTClient: routing table not ready")

82 // validateKeystoreSuffix rejects any suffix other than "0" or "1".

@@ -237,7 +244,7 @@ func LegacyProviderOpt(reprovideInterval time.Duration, strategy string, acceler

244 KeysOnly: true,

245 })

246 if err != nil {

240 - logger.Errorf("fetching AllKeysChain in provider ThroughputReport: %v", err)

247 + providerLog.Errorf("fetching AllKeysChain in provider ThroughputReport: %v", err)

248 return false

249 }

250 defer qr.Close()

@@ -258,7 +265,7 @@ func LegacyProviderOpt(reprovideInterval time.Duration, strategy string, acceler

265 // How long per block that lasts us.

266 expectedProvideSpeed := reprovideInterval / probableBigBlockstore

267 if avgProvideSpeed > expectedProvideSpeed {

261 - logger.Errorf(`

268 + providerLog.Errorf(`

269 🔔🔔🔔 Reprovide Operations Too Slow 🔔🔔🔔

270

271 Your node may be falling behind on DHT reprovides, which could affect content availability.

@@ -287,7 +294,7 @@ Learn more: https://github.com/ipfs/kubo/blob/master/docs/config.md#provide`,

294 }

295

296 if avgProvideSpeed > expectedProvideSpeed {

290 - logger.Errorf(`

297 + providerLog.Errorf(`

298 🔔🔔🔔 Reprovide Operations Too Slow 🔔🔔🔔

299

300 Your node is falling behind on DHT reprovides, which will affect content availability.

@@ -430,7 +437,7 @@ func findRootDatastoreSpec(spec map[string]any) map[string]any {

437 return spec

438 default:

439 if _, hasChild := spec["child"]; hasChild {

433 - logger.Warnw("unrecognized datastore wrapper type, using as-is",

440 + providerLog.Warnw("unrecognized datastore wrapper type, using as-is",

441 "type", spec["type"])

442 }

443 return spec

@@ -585,7 +592,7 @@ func purgeOrphanedKeystoreData(ctx context.Context, ds datastore.Batching) error

592 }

593 }

594 if count > 0 {

588 - logger.Infow("purged orphaned provider keystore data from shared datastore", "keys", count)

595 + providerLog.Infow("purged orphaned provider keystore data from shared datastore", "keys", count)

596 }

597 return nil

598 }

@@ -630,7 +637,7 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

637 if err != nil {

638 return nil, err

639 }

633 - logger.Infow("provider keystore: opened datastore", "suffix", suffix, "path", filepath.Join(keystoreBasePath, suffix))

640 + providerLog.Infow("provider keystore: opened datastore", "suffix", suffix, "path", filepath.Join(keystoreBasePath, suffix))

641 return ds, nil

642 }

643

@@ -638,7 +645,7 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

645 if err := validateKeystoreSuffix(suffix); err != nil {

646 return err

647 }

641 - logger.Infow("provider keystore: removing datastore from disk", "suffix", suffix, "path", filepath.Join(keystoreBasePath, suffix))

648 + providerLog.Infow("provider keystore: removing datastore from disk", "suffix", suffix, "path", filepath.Join(keystoreBasePath, suffix))

649 return os.RemoveAll(filepath.Join(keystoreBasePath, suffix))

650 }

651

@@ -656,7 +663,7 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

663 // NewResettableKeystore to avoid racing with reads on the same

664 // namespace.

665 if _, statErr := os.Stat(keystoreBasePath); os.IsNotExist(statErr) {

659 - logger.Infow("migrating provider keystore data from shared datastore to separate filesystem datastores", "path", keystoreBasePath)

666 + providerLog.Infow("migrating provider keystore data from shared datastore to separate filesystem datastores", "path", keystoreBasePath)

667 // Create a cancellable context for the purge. The OnStop hook

668 // below calls purgeCancel when the node receives a shutdown

669 // signal (e.g., SIGINT), which interrupts the purge loop

@@ -670,12 +677,12 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

677 })

678 if purgeErr := purgeOrphanedKeystoreData(purgeCtx, in.Repo.Datastore()); purgeErr != nil {

679 if purgeCtx.Err() != nil {

673 - logger.Infow("provider keystore migration interrupted by shutdown, will resume on next start")

680 + providerLog.Infow("provider keystore migration interrupted by shutdown, will resume on next start")

681 } else {

675 - logger.Warnw("provider keystore migration failed, will retry on next start", "error", purgeErr)

682 + providerLog.Warnw("provider keystore migration failed, will retry on next start", "error", purgeErr)

683 }

684 } else {

678 - logger.Infow("provider keystore migration completed")

685 + providerLog.Infow("provider keystore migration completed")

686 }

687 purgeCancel()

688 }

@@ -825,7 +832,7 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

832 return err

833 }

834 if err := in.Provider.RefreshSchedule(); err != nil {

828 - logger.Infow("refreshing provider schedule", "err", err)

835 + providerLog.Infow("refreshing provider schedule", "err", err)

836 }

837 return nil

838 }

@@ -842,16 +849,16 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

849 // we need to walk the DAG of objects matching the provide strategy,

850 // which can take a while.

851 strategy := cfg.Provide.Strategy.WithDefault(config.DefaultProvideStrategy)

845 - logger.Infow("provider keystore sync started", "strategy", strategy)

852 + providerLog.Infow("provider keystore sync started", "strategy", strategy)

853 if err := syncKeystore(ctx); err != nil {

854 if ctx.Err() == nil {

848 - logger.Errorw("provider keystore sync failed", "err", err, "strategy", strategy)

855 + providerLog.Errorw("provider keystore sync failed", "err", err, "strategy", strategy)

856 } else {

850 - logger.Debugw("provider keystore sync interrupted by shutdown", "err", err, "strategy", strategy)

857 + providerLog.Debugw("provider keystore sync interrupted by shutdown", "err", err, "strategy", strategy)

858 }

859 return

860 }

854 - logger.Infow("provider keystore sync completed", "strategy", strategy)

861 + providerLog.Infow("provider keystore sync completed", "strategy", strategy)

862 }()

863

864 gcCtx, c := context.WithCancel(context.Background())

@@ -868,7 +875,7 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

875 return

876 case <-ticker.C:

877 if err := syncKeystore(gcCtx); err != nil {

871 - logger.Errorw("provider keystore sync", "err", err)

878 + providerLog.Errorw("provider keystore sync", "err", err)

879 }

880 }

881 }

@@ -915,7 +922,7 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

922 // Close provider first - waits for all worker goroutines to exit.

923 // This ensures no code can access keystore after this returns.

924 if err := in.Provider.Close(); err != nil {

918 - logger.Errorw("error closing provider during shutdown", "error", err)

925 + providerLog.Errorw("error closing provider during shutdown", "error", err)

926 }

927

928 // Close keystore - safe now, provider is fully shut down

@@ -989,7 +996,7 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {

996 if prevQueuedWorkers && queuedWorkers && queueSize > prevQueueSize {

997 count++

998 if count >= consecutiveAlertsThreshold {

992 - logger.Errorf(`

999 + providerLog.Errorf(`

1000 🔔🔔🔔 Reprovide Operations Too Slow 🔔🔔🔔

1001

1002 Your node is falling behind on DHT reprovides, which will affect content availability.

@@ -1188,7 +1195,7 @@ func persistUniqueCount(ds datastore.Datastore, count uint64) {

1195 buf := make([]byte, 8)

1196 binary.BigEndian.PutUint64(buf, count)

1197 if err := ds.Put(context.Background(), datastore.NewKey(reprovideLastUniqueCountKey), buf); err != nil {

1191 - logger.Errorf("failed to persist unique count: %s", err)

1198 + providerLog.Errorf("failed to persist unique count: %s", err)

1199 }

1200 }

1201

@@ -1329,7 +1336,7 @@ func createKeyProvider(strategyFlag config.ProvideStrategy, fpRate uint, in prov

1336 if ctx.Err() == nil {

1337 persistUniqueCount(ds, tracker.Count())

1338 }

1332 - logger.Infow("unique reprovide cycle finished",

1339 + providerLog.Infow("unique reprovide cycle finished",

1340 "providedCIDs", tracker.Count(),

1341 "skippedBranches", tracker.Deduplicated())

1342 close(ch)

@@ -1343,7 +1350,7 @@ func createKeyProvider(strategyFlag config.ProvideStrategy, fpRate uint, in prov

1350 }

1351 }()

1352

1346 - logger.Infow("unique reprovide cycle started",

1353 + providerLog.Infow("unique reprovide cycle started",

1354 "expectedItems", expectedItems,

1355 "previousCount", count,

1356 )

@@ -1406,7 +1413,7 @@ func handleStrategyChange(strategy string, provider DHTProvider, ds datastore.Da

1413

1414 previous, changed, err := detectStrategyChange(ctx, strategy, ds)

1415 if err != nil {

1409 - logger.Error("cannot read previous reprovide strategy", "err", err)

1416 + providerLog.Error("cannot read previous reprovide strategy", "err", err)

1417 return

1418 }

1419

@@ -1414,11 +1421,11 @@ func handleStrategyChange(strategy string, provider DHTProvider, ds datastore.Da

1421 return

1422 }

1423

1417 - logger.Infow("Provide.Strategy changed, clearing provide queue", "previous", previous, "current", strategy)

1424 + providerLog.Infow("Provide.Strategy changed, clearing provide queue", "previous", previous, "current", strategy)

1425 provider.Clear()

1426

1427 if err := persistStrategy(ctx, strategy, ds); err != nil {

1421 - logger.Error("cannot update reprovide strategy", "err", err)

1428 + providerLog.Error("cannot update reprovide strategy", "err", err)

1429 }

1430 }

1431

docs/debug-guide.md

+18

@@ -7,6 +7,7 @@ This is a document for helping debug Kubo. Please add to it if you can!

7 - [General performance debugging guidelines](#general-performance-debugging-guidelines)

8 - [Table of Contents](#table-of-contents)

9 - [Beginning](#beginning)

10 + - [Known logger subsystems](#known-logger-subsystems)

11 - [Analyzing the stack dump](#analyzing-the-stack-dump)

12 - [Analyzing the CPU Profile](#analyzing-the-cpu-profile)

13 - [Analyzing vars and memory statistics](#analyzing-vars-and-memory-statistics)

@@ -38,6 +39,23 @@ If you feel intrepid, you can dump this information and investigate it yourself:

39 - `ipfs diag sys > ipfs.sysinfo`

42 +### Known logger subsystems

43 +

44 +`GOLOG_LOG_LEVEL` matches subsystem names exactly (no prefix or wildcard matching beyond `*` for "all subsystems"). The same names work with the runtime command `ipfs log level <subsystem> <level>`. The list below covers the outbound provide/reprovide pipeline, which spans multiple packages and therefore multiple subsystems.

45 +

46 +| Subsystem | Source | Purpose |

47 +| --- | --- | --- |

48 +| `provider` | kubo `core/node`, boxo `provider` | Kubo provider orchestration (keystore lifecycle, strategy changes, reprovide cycle start/finish, throughput alarms) and boxo's legacy provider system (active when `Provide.DHT.SweepEnabled=false` or for non-DHT routers) |

49 +| `dht/provider` | `go-libp2p-kad-dht` | Sweep-based DHT provider (active when `Provide.DHT.SweepEnabled=true`, the default), including the buffered wrapper, keystore, and resettable keystore |

50 +| `dht/provider/lan` | `go-libp2p-kad-dht` (dual) | LAN half of the dual DHT provider; the WAN half reuses `dht/provider` |

51 +| `dsqueue` | `go-dsqueue` | Generic datastore queue used by the legacy provider queue |

52 +

53 +To see everything the provide system emits, for example at `debug` level:

54 +

55 +```shell

56 +GOLOG_LOG_LEVEL="provider=debug,dht/provider=debug,dht/provider/lan=debug" ipfs daemon

57 +```

58 +

59 ### Analyzing the stack dump

61 The first thing to look for is hung goroutines -- any goroutine that's been stuck

docs/environment-variables.md

@@ -76,6 +76,8 @@ GOLOG_LOG_LEVEL="error,core/server=debug" ipfs daemon

77 Logging can also be configured at runtime, both globally and on a per-subsystem basis, with the `ipfs log` command.

79 +See [Known logger subsystems](./debug-guide.md#known-logger-subsystems) for subsystem names related to the provide/reprovide pipeline.

80 +

81 ## `GOLOG_LOG_FMT`

83 Specifies the log message format. It supports the following values:

test/cli/provider_test.go

+1 -1

@@ -1270,7 +1270,7 @@ func TestProviderUniqueDedupLogging(t *testing.T) {

1270 nodes[0].StartDaemonWithReq(harness.RunRequest{

1271 CmdOpts: []harness.CmdOpt{

1272 harness.RunWithEnv(map[string]string{

1273 - "GOLOG_LOG_LEVEL": "error,dagwalker=info,core:constructor=info",

1273 + "GOLOG_LOG_LEVEL": "error,dagwalker=info,provider=info",

1274 }),

1275 },

1276 }, "")