#35630·go-ethereum

core/filtermaps: eth_getLogs matcher goroutines never released after client disconnect; accumulated lock waiters starve the head renderer into a permanent livelock

Author: AntonieDavidCreated Sep 2, 2026Updated Sep 7, 2026

Summary

On Robinhood mainnet (an Arbitrum Orbit chain running Nitro, which embeds a fork of go-ethereum), we have repeatedly hit a state where eth_getLogs handler goroutines are never released after the request is cancelled, and the accumulated stuck goroutines starve the filtermaps head renderer into a permanent livelock. Once a node enters this state:

  • eth_getLogs over ranges at or near the indexed head takes 12–15s+ (healthy baseline on the same nodes: 4–6 ms). Ranges far behind the head degrade less (~1.5s).
  • The log index head renderer, which normally keeps up with the chain silently, falls behind and logs Log index head rendering finished ... elapsed=30s+ continuously for every ~340-block batch — a net throughput of ~8–11 blocks/s against a chain producing ~10 blocks/s, so it never converges (one node ran a single catch-up pass for 1h30m+ and lost ground: processed=42,729 remaining=9,238 elapsed=1h30m6s with remaining not shrinking).
  • Goroutine count grows monotonically and never comes back down. We measured 97,874 goroutines on one affected node (healthy baseline on identical nodes under comparable load: ~300) while only ~7 HTTP connections were actually open.
  • Everything else on the node stays healthy: block execution keeps up with the chain head, other RPC methods respond normally, CPU is far from saturated (~80% idle at capture time), no disk I/O pressure.
  • The node never recovers on its own. We removed one affected node from the serving pool entirely and left it with zero query traffic for 45+ minutes: goroutine count did not decrease, render batches stayed at ~30s, and local eth_getLogs probes stayed slow. Only a process restart clears it — and after a restart with no traffic, the same node rendered its 17,585-block index backlog in 10 seconds (~1,750 blocks/s, i.e. ~200x the livelocked throughput) and returned to sub-10ms eth_getLogs, with goroutines back to ~230. So the hardware, the database and the index itself are fine; the sick state is purely in-process.

We captured a full goroutine dump (debug_stacks, 68 MB) from a live affected node. The evidence points to cancelled eth_getLogs requests leaking goroutines inside core/filtermaps, whose accumulated indexLock.RLock() pressure starves the renderer's write lock — details below.

Setup

  • Network: Robinhood mainnet (Arbitrum Orbit chain, ~10 blocks/s block rate, busy log emission)
  • Nodes: archive nodes, log index fully enabled and indexed to head; PBSS/pebble
  • Binary: Nitro v3.11.3-beb2108 (also reproduced on v3.11.2-3599aca), go1.25.13
  • The embedded go-ethereum is OffchainLabs/go-ethereum @ f3a966e6c328fc4cf1762e38ff5ddd47724f70ba; we diffed core/filtermaps/matcher.go and core/filtermaps/matcher_backend.go at that commit against upstream master and v1.17.5 — they are byte-identical to upstream (modulo one comment typo).

Traffic profile that triggers it: sustained concurrent eth_getLogs with address + topic filters over ~1,000–9,000-block ranges at/near the head, where a meaningful share of in-flight requests get cancelled (connection closed) while still running, and new requests keep arriving.

Forensic evidence from a live affected node

Aggregating the 68 MB goroutine dump (~31k goroutine stacks) by state and top frame:

  count  state                              top frame
   5722  [sync.RWMutex.RLock]               sync.runtime_SemacquireRWMutexR
   4514  [sync.Mutex.Lock]                  internal/sync.runtime_SemacquireMutex
   1929  [sync.WaitGroup.Wait, 126 minutes] sync.runtime_SemacquireWaitGroup
   1893  [select, 126 minutes]              core/filtermaps.(*matcherEnv).process
   1519  [select, 136 minutes]              core/filtermaps.(*matcherEnv).process
   1389  [sync.WaitGroup.Wait, 136 minutes] sync.runtime_SemacquireWaitGroup
   1249  [sync.WaitGroup.Wait, 127 minutes] sync.runtime_SemacquireWaitGroup
   1174  [select, 127 minutes]              core/filtermaps.(*matcherEnv).process
   ...  (thousands more of the same shapes, blocked 125–137 minutes)

The blocked durations all date back to a single period of heavy eth_getLogs load with many cancellations. All of these requests had long since been cancelled — the underlying connections were closed hours before the dump was taken (only ~7 connections were open at capture time).

Representative stack of a stuck request coordinator (blocked 136 minutes):

goroutine 1409650133 [select, 136 minutes]:
github.com/ethereum/go-ethereum/core/filtermaps.(*matcherEnv).process(0xc23952d180)
        core/filtermaps/matcher.go:193
github.com/ethereum/go-ethereum/core/filtermaps.GetPotentialMatches(...)
        core/filtermaps/matcher.go:126
github.com/ethereum/go-ethereum/eth/filters.(*Filter).indexedLogs(...)
        eth/filters/filter.go:411
github.com/ethereum/go-ethereum/eth/filters.(*searchSession).searchInRange(...)
        eth/filters/filter.go:261
github.com/ethereum/go-ethereum/eth/filters.(*searchSession).doSearchIteration(...)
        eth/filters/filter.go:306
github.com/ethereum/go-ethereum/eth/filters.(*Filter).rangeLogs(...)
        eth/filters/filter.go:392
github.com/ethereum/go-ethereum/eth/filters.(*Filter).Logs(...)
        eth/filters/filter.go:144
github.com/ethereum/go-ethereum/eth/filters.(*FilterAPI).GetLogs(...)
        eth/filters/api.go:486

Representative stack of a stuck matcher worker:

goroutine 1409495579 [sync.RWMutex.RLock]:
sync.(*RWMutex).RLock(...)
github.com/ethereum/go-ethereum/core/filtermaps.(*FilterMapsMatcherBackend).GetLogByLvIndex(...)
        core/filtermaps/matcher_backend.go:115
github.com/ethereum/go-ethereum/core/filtermaps.(*matcherEnv).getLogsFromMatches(...)
        core/filtermaps/matcher.go:272
github.com/ethereum/go-ethereum/core/filtermaps.(*matcherEnv).processEpoch(...)
        core/filtermaps/matcher.go:252
created by github.com/ethereum/go-ethereum/core/filtermaps.(*matcherEnv).process
        core/filtermaps/matcher.go:181

Renderer-side symptoms on the same node (filtermaps_maps_rendertime quantiles, ns): p50 ≈ 1.3 ms, p99 ≈ 3.3 s, p99.9 ≈ 6.7 s. Healthy baseline on an identical node serving comparable traffic: p50 ≈ 290 µs, p99 ≈ 933 µs. Per-map render time is what collapses — consistent with the renderer repeatedly waiting to acquire indexLock against thousands of queued readers.

Analysis

Reading the code at the blocked sites (identical upstream):

  1. The coordinator loop in (*matcherEnv).process (matcher.go:192-218) selects only on task dispatch and task completion — there is no <-m.ctx.Done() case. If the workers can't make progress, the coordinator blocks forever, and its defer { close(taskCh); wg.Wait() } pins the request handler goroutine along with it. Closing the connection cancels the request context, but nothing in this loop observes it.

  2. FilterMapsMatcherBackend.GetLogByLvIndex and GetBlockLvPointer (matcher_backend.go) accept a ctx parameter but never use it — they do a bare, uncancellable fm.f.indexLock.RLock(). This is where the worker goroutines sit. (Within the backend, only SyncLogIndex observes ctx.Done() — that one was made cancellable after #31420.)

The livelock loop this produces on a fast chain:

  • The head renderer needs indexLock (write) frequently — at ~10 blocks/s it is active nearly all the time, unlike on Ethereum mainnet where it finishes a head batch quickly and goes idle between blocks.
  • A burst of concurrent eth_getLogs piles readers onto indexLock. Queries slow down and start getting cancelled mid-flight — but the cancelled handlers never exit, so each new request that replaces a cancelled one adds ~5 more goroutines (coordinator + 4 workers) that permanently participate in lock contention.
  • Renderer throughput drops below the chain's block production rate, so the index head lags permanently; searches near the head get even slower (more waiting on the renderer/lock), producing more timeouts and more stuck goroutines. Self-sustaining until restart.

The zero-traffic experiment supports the "stuck goroutines, not load" conclusion: with all query traffic removed for 45+ minutes, the renderer still only managed ~30s per ~340-block batch, because the thousands of parked readers never went away. After a restart (index state on disk untouched), the same node rendered ~1,750 blocks/s.

We believe the fast block rate is why an Orbit chain hits this easily while Ethereum mainnet rarely would: the contention window between matchers and the renderer is essentially always open at 10 blocks/s, and any latency degradation immediately increases the rate of cancelled in-flight requests.

Related prior reports of uncancellable waits in this subsystem, same family but different blocking sites: #31420 (goroutine stuck in SyncLogIndex, fixed by #31429) and #31700 (search vs. unindexing deadlock, fixed by #31704 / #31708).

Reproduction attempt (how we'd try to reproduce from scratch)

  1. Archive node with the log index enabled and fully rendered to head, on a chain with a fast block rate (~10 blocks/s) and steady log emission.
  2. Send sustained concurrent eth_getLogs (say 50–200 concurrent) with address+topic filters over 1,000–9,000-block ranges near the head, cancelling requests that run longer than a few seconds (close the connection) while keeping the request rate up.
  3. Watch: goroutine count (it climbs monotonically once cancellations begin and never drops), Log index head rendering finished ... elapsed= lines growing into tens of seconds, and per-map render time quantiles collapsing.
  4. Stop all traffic: the state persists indefinitely. Restart the process: clean recovery within seconds.

A node whose renderer is mid-catch-up (e.g. freshly started with some head lag) enters the state faster, but one of our affected nodes had 4+ days of uptime and entered it purely from the query load, so a restart is not a required ingredient.

Possible directions

Take these with a grain of salt:

  • Add a case <-m.ctx.Done(): return nil, m.ctx.Err() to the coordinator select in (*matcherEnv).process, and make the workers check ctx between tasks (and ideally inside processEpoch's map/log loops), so cancelled requests actually unwind.
  • Honor ctx in the MatcherBackend methods that currently ignore it (GetLogByLvIndex, GetBlockLvPointer, GetFilterMapRows) — at minimum a ctx.Err() check before the lock acquisition so a cancelled search stops queueing new reads; a cancellable lock acquisition would be stronger.
  • Bound total matcher concurrency with a semaphore so that even a pathological request storm can't multiply lock waiters without limit.
  • Consider protecting the renderer from reader starvation (e.g. chunking or yielding on the reader side, or a renderer-priority locking scheme), since on fast chains sustained search load can otherwise push index throughput below the block production rate even without the leak.

We still have the full 68 MB goroutine dump, metrics snapshots, and node logs from the affected nodes, and can share them privately or run additional diagnostics on request.