core/bloombits: fix deadlock when matcher session hits an error

[msmania]

core/bloombits: fix a deadlock when a matcher session hits an error

Problem description

A deadlock occurs when a pruned node receives eth_getLogs for pruned blocks. We hit this deadlock in bsc and avalanche's subnet-evm.

This deadlock didn't happen on Ethereum with this repo's geth. Probably it's because the pruning mechanism is different.

As discussed below, however, the root cause is in core/bloombits and its code is the same as bsc. Any component consuming core/bloombits may hit this deadlock.

Root cause and Fix

Here are the goroutines causing the deadlock. Please note that this info is from bsc. The functions names are slightly different from the current geth.

1. Goroutine running GetLogs is waiting on s.closer

  Goroutine 325 - User: /data/bin/go/src/runtime/sema.go:77 sync.runtime_SemacquireMutex (0x497766) [timer goroutine (idle) 13036920152269]
...snip...
 2  0x0000000000477c11 in runtime.semacquire1
    at /data/bin/go/src/runtime/sema.go:160
 3  0x0000000000497766 in sync.runtime_SemacquireMutex
    at /data/bin/go/src/runtime/sema.go:77
 4  0x00000000004d190d in sync.(*Mutex).lockSlow
    at /data/bin/go/src/sync/mutex.go:171
 5  0x00000000004d15ef in sync.(*Mutex).Lock
    at /data/bin/go/src/sync/mutex.go:90
 6  0x00000000004d1ce9 in sync.(*Once).doSlow
    at /data/bin/go/src/sync/once.go:70
 7  0x00000000004d1c65 in sync.(*Once).Do
    at /data/bin/go/src/sync/once.go:65
 8  0x00000000016f033d in github.com/ethereum/go-ethereum/core/bloombits.(*MatcherSession).Close
    at /data/src/bsc/core/bloombits/matcher.go:527
 9  0x0000000001f4f74b in github.com/ethereum/go-ethereum/eth/filters.(*Filter).indexedLogs.func1
    at /data/src/bsc/eth/filters/filter.go:224
10  0x0000000000461a73 in runtime.deferreturn
    at /data/bin/go/src/runtime/panic.go:476
11  0x0000000001f4f6ae in github.com/ethereum/go-ethereum/eth/filters.(*Filter).indexedLogs
    at /data/src/bsc/eth/filters/filter.go:240
12  0x0000000001f4e0f1 in github.com/ethereum/go-ethereum/eth/filters.(*Filter).Logs
    at /data/src/bsc/eth/filters/filter.go:194
13  0x0000000001f49daa in github.com/ethereum/go-ethereum/eth/filters.(*PublicFilterAPI).GetLogs
    at /data/src/bsc/eth/filters/api.go:478

2. s.closer is owned by Goroutine running MatcherSession.Multiplex, which is waiting on s.pend

  Goroutine 1512 - User: /data/bin/go/src/runtime/sema.go:62 sync.runtime_Semacquire (0x497647) [semacquire 13036920152269]
  ...snip...
 2  0x0000000000477c11 in runtime.semacquire1
    at /data/bin/go/src/runtime/sema.go:160
 3  0x0000000000497647 in sync.runtime_Semacquire
    at /data/bin/go/src/runtime/sema.go:62
 4  0x00000000004d44f7 in sync.(*WaitGroup).Wait
    at /data/bin/go/src/sync/waitgroup.go:116
 5  0x00000000016f03a5 in github.com/ethereum/go-ethereum/core/bloombits.(*MatcherSession).Close.func1
    at /data/src/bsc/core/bloombits/matcher.go:530
 6  0x00000000004d1dd8 in sync.(*Once).doSlow
    at /data/bin/go/src/sync/once.go:74
 7  0x00000000004d1c65 in sync.(*Once).Do
    at /data/bin/go/src/sync/once.go:65
 8  0x00000000016f033d in github.com/ethereum/go-ethereum/core/bloombits.(*MatcherSession).Close
    at /data/src/bsc/core/bloombits/matcher.go:527
 9  0x00000000016f1272 in github.com/ethereum/go-ethereum/core/bloombits.(*MatcherSession).Multiplex
    at /data/src/bsc/core/bloombits/matcher.go:640
10  0x0000000001f94605 in github.com/ethereum/go-ethereum/eth.(*EthAPIBackend).ServiceFilter.func1
    at /data/src/bsc/eth/api_backend.go:384
11  0x000000000049bd01 in runtime.goexit
    at /data/bin/go/src/runtime/asm_amd64.s:1598

3. s.pend needs one more "Done" in Matcher.run in the following Goroutine, which is waiting on channels.

  Goroutine 460 - User: /data/src/bsc/core/bloombits/matcher.go:410 github.com/ethereum/go-ethereum/core/bloombits.(*Matcher).distributor (0x16ee95f) [select 13036920152269]
0  0x0000000000465bdd in runtime.gopark
   at /data/bin/go/src/runtime/proc.go:382
1  0x0000000000476eea in runtime.selectgo
   at /data/bin/go/src/runtime/select.go:327
2  0x00000000016ee95f in github.com/ethereum/go-ethereum/core/bloombits.(*Matcher).distributor
   at /data/src/bsc/core/bloombits/matcher.go:410
3  0x00000000016ec5be in github.com/ethereum/go-ethereum/core/bloombits.(*Matcher).run.func2
   at /data/src/bsc/core/bloombits/matcher.go:252
4  0x00000000009318d8 in github.com/panjf2000/ants/v2.(*goWorker).run.func1
   at /home/john/go/pkg/mod/github.com/panjf2000/ants/[email protected]/worker.go:70
5  0x000000000049bd01 in runtime.goexit
   at /data/bin/go/src/runtime/asm_amd64.s:1598

The 2nd goroutine did close the s.quit channel before waiting on s.pend. When the 3rd goroutine received that signal, it set the shutdown to nil, but at that time allocs was 1, so the loop in distributor still continued.

What the 3rd goroutine is waiting is data on m.deliveries. If that happens, the distributor returns, s.pending is marked done, and all goroutines resume.

The reason why m.deliveries is receiving no data is that the 2nd goroutine is stuck on s.Close() before s.deliverSections that sends data to m.deliveries.

Therefore, the proposed fix is to call s.deliverSections in MatcherSession.Multiplex before calling s.Close().

[jsvisa]

A deadlock occurs when a pruned node receives eth_getLogs for pruned blocks.

Do you mean this issue occurred when the ancient block data was pruned? If so, go-ethereum didn't prune any ancient data, so I think this issue can't trigger.

[MariusVanDerWijden]

Everyone is merging PRs right before I can review them :(

[msmania]

Do you mean this issue occurred when the ancient block data was pruned? If so, go-ethereum didn't prune any ancient data, so I think this issue can't trigger.

Yes, that's how the issue was emerged in BSC. Even if deadlock was not reproducible in Ethereum, the root cause was still in this repo's core/bloombits and this patch would prevent unknown problems in the future.

@fjl Thank you for merging this! I'll port this to other applicable blockchains.