fix(pins): snapshot index before emitting pins (#11290)
* chore: bump boxo to ipfs/boxo#1140 picks up dspinner fix that snapshots the index before emitting pins, avoiding the streaming lock convoy. * docs: changelog entry for pinner stall fix * docs: clarify pinner snapshot behavior * chore: bump boxo to include ipfs/boxo#1146 Picks up the fix for "panic: pebble: closed" on shutdown (#11292): the dspinner streamIndex goroutine now recovers from any datastore panic and reports it as an error on the output channel, so the daemon exits cleanly instead of crashing when the datastore closes before pin enumeration drains. * fix(provider): quiet keystore-close on shutdown When the daemon shuts down, the keystore Close fires while the startup sync goroutine may still be in flight: the OnStart ctx is not yet cancelled, so ResetCids returning keystore.ErrClosed gets logged at Error as "sync failed". Treat keystore.ErrClosed the same as a cancelled ctx and log at Debug as "interrupted by shutdown". Apply the same rule to the periodic reprovide GC loop (whose error log got a unified message in the process). * test(cli): keystore-close log + pin ls shutdown Adds TestProviderKeystoreSyncShutdownQuiet, a CLI test that: 1. Verifies no shutdown-caused keystore-sync error (err="keystore is closed" or err="context canceled") is logged at Error level. Scans stderr line-by-line so unrelated Error logs (e.g. "reset already in progress" from the startup+periodic overlap at tight Intervals) do not false-positive the assertion. 2. Runs `ipfs pin ls --stream` against the live daemon, shuts the daemon down mid-stream, and asserts the CLI returns within 15s, does not observe a daemon panic, and produces a meaningful error message if it exited non-zero. Uses Provide.DHT.Interval=10ms so the periodic reprovide loop is always inside ResetCids when StopDaemon fires, making the shutdown race deterministic enough to catch the regression on most runs (verified empirically against the pre-fix provider.go).
Marcin Rataj committed
Apr 23, 2026 at 21:45 UTC
8416f38b84384ad1d8b3d0cc6a0a95abe5c61cd7
4 files changed
+157
-5
core/node/provider.go
+12
-4
@@ -851,10 +851,14 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {
851
strategy := cfg.Provide.Strategy.WithDefault(config.DefaultProvideStrategy)
852
providerLog.Infow("provider keystore sync started", "strategy", strategy)
853
if err := syncKeystore(ctx); err != nil {
854
- if ctx.Err() == nil {
855
- providerLog.Errorw("provider keystore sync failed", "err", err, "strategy", strategy)
856
- } else {
854
+ // ErrClosed means the keystore was closed by the shutdown
855
+ // hook while this goroutine was still in flight: the
856
+ // OnStart ctx is not cancelled yet, so we classify the
857
+ // failure as shutdown explicitly.
858
+ if ctx.Err() != nil || errors.Is(err, keystore.ErrClosed) {
859
providerLog.Debugw("provider keystore sync interrupted by shutdown", "err", err, "strategy", strategy)
860
+ } else {
861
+ providerLog.Errorw("provider keystore sync failed", "err", err, "strategy", strategy)
862
}
863
return
864
}
@@ -875,7 +879,11 @@ func SweepingProviderOpt(cfg *config.Config) fx.Option {
879
return
880
case <-ticker.C:
881
if err := syncKeystore(gcCtx); err != nil {
878
- providerLog.Errorw("provider keystore sync", "err", err)
882
+ if gcCtx.Err() != nil || errors.Is(err, keystore.ErrClosed) {
883
+ providerLog.Debugw("provider keystore sync interrupted by shutdown", "err", err)
884
+ } else {
885
+ providerLog.Errorw("provider keystore sync failed", "err", err)
886
+ }
887
}
888
}
889
}
docs/changelogs/v0.42.md
+7
@@ -10,6 +10,7 @@ This release was brought to you by the [Shipyard](https://ipshipyard.com/) team.
10
11
- [Overview](#overview)
12
- [🔦 Highlights](#-highlights)
13
+ - [🐛 Fixed pin operations hanging under pinned reprovide strategies](#-fixed-pin-operations-hanging-under-pinned-reprovide-strategies)
14
- [📝 Changelog](#-changelog)
15
- [👨👩👧👦 Contributors](#-contributors)
16
@@ -17,6 +18,12 @@ This release was brought to you by the [Shipyard](https://ipshipyard.com/) team.
18
19
### 🔦 Highlights
20
21
+#### 🐛 Fixed pin operations hanging under pinned reprovide strategies
22
+
23
+`ipfs pin ls`, `ipfs add`, and other pin-touching operations could block for hours on nodes running with [`Provide.Strategy`](https://github.com/ipfs/kubo/blob/master/docs/config.md#providestrategy) set to `pinned`, `roots`, or `pinned+mfs` (including `+unique` / `+entities` variants). The pin index held a read lock for the entire reprovide cycle, which on large pinsets takes many hours. Any pin operation issued during that window blocked, and further `pin ls` / `ipfs add` calls piled up behind it until the cycle finished.
24
+
25
+The pinner now snapshots the index under the read lock and releases it before the reprovider starts, so pin operations are no longer blocked by the reprovide cycle. The default `Provide.Strategy=all` was not affected.
26
+
27
### 📝 Changelog
28
29
### 👨👩👧👦 Contributors
docs/config.md
+1
-1
@@ -2157,7 +2157,7 @@ The `+unique` and `+entities` modifiers can be appended to `pinned`, `mfs`, or `
2157
2158
#### Memory during reprovide
2159
2160
-Reproviding larger pinsets using the `mfs`, `pinned`, `pinned+mfs` or `roots` strategies requires additional memory, with an estimated ~1 GiB of RAM per 20 million CIDs. This is due to the use of a buffered provider, which loads all CIDs into memory to avoid holding a lock on the entire pinset during the reprovide cycle.
2160
+Reproviding larger pinsets using the `mfs`, `pinned`, `pinned+mfs` or `roots` strategies requires additional memory, with an estimated ~1 GiB of RAM per 20 million CIDs. This is because the pinner snapshots the pin index into memory at the start of each reprovide cycle so that pin/unpin are not blocked while the DHT reprovider works over the snapshot.
2161
2162
With `+unique` or `+entities`, a bloom filter replaces the in-memory CID set, significantly reducing memory usage:
2163
test/cli/provider_test.go
+137
@@ -1585,3 +1585,140 @@ func dirExists(path string) bool {
1585
info, err := os.Stat(path)
1586
return err == nil && info.IsDir()
1587
}
1588
+
1589
+// TestProviderKeystoreSyncShutdownQuiet verifies two shutdown UX
1590
+// guarantees for a daemon running the sweeping provider with a
1591
+// pin-walking strategy (see ipfs/kubo#11292):
1592
+//
1593
+// 1. Shutdown-caused keystore-sync errors never appear at Error
1594
+// level. The fix classifies keystore.ErrClosed and context
1595
+// cancellation as shutdown-caused and logs at Debug as
1596
+// "interrupted by shutdown" instead.
1597
+// 2. `ipfs pin ls --stream` running against the daemon returns a
1598
+// meaningful error (no panic, no hang) when the daemon is
1599
+// shutting down mid-stream.
1600
+//
1601
+// Determinism: with Provide.DHT.Interval=10ms the periodic
1602
+// reprovide goroutine runs syncKeystore back-to-back (ticks coalesce
1603
+// under the select), so it is always mid-sync when StopDaemon
1604
+// closes the keystore. The line-scan below fails on the exact
1605
+// Error+err=keystore-closed/context-canceled combination the old
1606
+// code emitted. Empirically this catches the regression on most
1607
+// runs (~3 of 5 on a fast workstation); the first few bug-free
1608
+// runs were verified by temporarily reverting core/node/provider.go.
1609
+func TestProviderKeystoreSyncShutdownQuiet(t *testing.T) {
1610
+ t.Parallel()
1611
+
1612
+ h := harness.NewT(t)
1613
+ node := h.NewNode().Init()
1614
+ node.SetIPFSConfig("Provide.DHT.SweepEnabled", true)
1615
+ node.SetIPFSConfig("Provide.Enabled", true)
1616
+ node.SetIPFSConfig("Provide.Strategy", "pinned+mfs+entities")
1617
+ // Tight Interval: once the startup sync completes, the periodic
1618
+ // goroutine runs syncKeystore back-to-back (ticks coalesce under
1619
+ // the select), so it is always mid-sync when StopDaemon fires.
1620
+ // This makes the shutdown interrupt deterministic. Briefly
1621
+ // during startup the first periodic tick may overlap the startup
1622
+ // sync and emit "reset already in progress" at Error; the log
1623
+ // scan below explicitly ignores that unrelated class of error.
1624
+ node.SetIPFSConfig("Provide.DHT.Interval", "10ms")
1625
+ node.SetIPFSConfig("Bootstrap", []string{})
1626
+
1627
+ // Seed recursive pins so the keystore sync has meaningful work.
1628
+ // Offline bulk add + bulk pin is much faster than per-file
1629
+ // IPFSAddStr calls for this count.
1630
+ const nPins = 500
1631
+ dir := t.TempDir()
1632
+ for i := range nPins {
1633
+ require.NoError(t, os.WriteFile(
1634
+ filepath.Join(dir, fmt.Sprintf("f%04d", i)),
1635
+ fmt.Appendf(nil, "keystore-shutdown-content-%d", i),
1636
+ 0o600,
1637
+ ))
1638
+ }
1639
+ // --pin=false so the wrapping dir is not auto-pinned; each file
1640
+ // is then pinned individually below to get nPins separate pin
1641
+ // index entries (one big recursive pin would not exercise the
1642
+ // pin-index streamIndex walk the same way).
1643
+ addRes := node.IPFS("add", "-r", "-q", "--pin=false", dir)
1644
+ addedCIDs := strings.Split(strings.TrimSpace(addRes.Stdout.String()), "\n")
1645
+ require.GreaterOrEqual(t, len(addedCIDs), nPins, "expected at least %d CIDs from bulk add", nPins)
1646
+ pinArgs := append([]string{"pin", "add"}, addedCIDs[:nPins]...)
1647
+ node.IPFS(pinArgs...)
1648
+
1649
+ node.StartDaemonWithReq(harness.RunRequest{
1650
+ CmdOpts: []harness.CmdOpt{
1651
+ harness.RunWithEnv(map[string]string{
1652
+ // Debug for the provider subsystem so the shutdown
1653
+ // Debug line is visible for post-hoc inspection.
1654
+ "GOLOG_LOG_LEVEL": "error,provider=debug",
1655
+ }),
1656
+ },
1657
+ }, "")
1658
+
1659
+ // Wait for the startup sync to complete so periodic has sole
1660
+ // access to the keystore when we shut down.
1661
+ require.Eventually(t, func() bool {
1662
+ return strings.Contains(node.Daemon.Stderr.String(), "provider keystore sync completed")
1663
+ }, 30*time.Second, 50*time.Millisecond, "startup keystore sync should complete")
1664
+
1665
+ // Let periodic reprovide fire several times.
1666
+ time.Sleep(1 * time.Second)
1667
+
1668
+ // Kick off `ipfs pin ls --stream` against the live RPC. The
1669
+ // server-side channel is held by the pinner's streamIndex
1670
+ // goroutine; when StopDaemon below tears down the keystore and
1671
+ // datastore, the HTTP stream closes under the CLI, which must
1672
+ // exit cleanly with a meaningful error (no panic, no hang).
1673
+ pinLsDone := make(chan *harness.RunResult, 1)
1674
+ go func() {
1675
+ pinLsDone <- node.RunIPFS("pin", "ls", "--stream")
1676
+ }()
1677
+ // Brief delay so the pin ls RPC has started streaming.
1678
+ time.Sleep(100 * time.Millisecond)
1679
+
1680
+ node.StopDaemon()
1681
+
1682
+ // --- Daemon-side assertions ---
1683
+
1684
+ daemonLog := node.Daemon.Stderr.String()
1685
+
1686
+ // Scan for the specific bug pattern: an Error-level line from
1687
+ // the provider subsystem about "keystore sync" whose err field
1688
+ // is the shutdown-caused "keystore is closed" or "context
1689
+ // canceled". The fix routes those to Debug; only unrelated
1690
+ // errors (e.g. "reset already in progress" from test-induced
1691
+ // overlap) remain at Error and are ignored by this check.
1692
+ for line := range strings.SplitSeq(daemonLog, "\n") {
1693
+ if !strings.Contains(line, "\tERROR\t") {
1694
+ continue
1695
+ }
1696
+ if !strings.Contains(line, "provider keystore sync") {
1697
+ continue
1698
+ }
1699
+ if strings.Contains(line, `"err": "keystore is closed"`) ||
1700
+ strings.Contains(line, `"err": "context canceled"`) {
1701
+ t.Errorf("shutdown-caused keystore sync error should be logged at Debug, got Error:\n%s", line)
1702
+ }
1703
+ }
1704
+
1705
+ // --- Client-side assertions (ipfs pin ls --stream) ---
1706
+
1707
+ var pinLs *harness.RunResult
1708
+ select {
1709
+ case pinLs = <-pinLsDone:
1710
+ case <-time.After(15 * time.Second):
1711
+ t.Fatal("ipfs pin ls --stream did not return within 15s of daemon shutdown")
1712
+ }
1713
+
1714
+ pinLsOut := pinLs.Stdout.String() + pinLs.Stderr.String()
1715
+ require.NotContains(t, pinLsOut, "panic:",
1716
+ "ipfs pin ls must not observe a daemon panic")
1717
+ // Either the stream drained before shutdown (exit 0) or the
1718
+ // server dropped it mid-stream (non-zero exit with a meaningful
1719
+ // error message). Silent non-zero exits are confusing and fail.
1720
+ if pinLs.ExitCode() != 0 {
1721
+ require.NotEmpty(t, strings.TrimSpace(pinLs.Stderr.String()),
1722
+ "pin ls exited non-zero but produced no error message")
1723
+ }
1724
+}