blockchain+mempool: deep re-orgs on testnet lead to double mutex unlock

[discoltk]

It seems that someone forked testnet, and btcd crashed.

The node in question was built from commit f3ec130

Apr 13 23:28:19 dev-btcd btcd[1514]: 2020-04-13 23:28:19.407 [INF] SYNC: Processed 6 blocks in the last 12.1s (9 transactions, height 1702711, 2020-04-13 23:28:21 +0000 UTC)
Apr 13 23:28:28 dev-btcd btcd[1514]: 2020-04-13 23:28:28.224 [INF] CHAN: Adding orphan block 000000000001d9a563b487126986b96858ddca15c7695bb77753a2b8c76833dc with parent 00000000000193aa0683a1aa681e6687bf312f9d969555068f5238524b7f8035
Apr 13 23:28:28 dev-btcd btcd[1514]: 2020-04-13 23:28:28.363 [INF] CHAN: FORK: Block 00000000000193aa0683a1aa681e6687bf312f9d969555068f5238524b7f8035 forks the chain at height 1702712/block 0000000000002328efac5cee7c3e8b0fdc48dcf3c047fec068ad89b6f99190ab, but does not cause a reorganize
Apr 13 23:28:28 dev-btcd btcd[1514]: 2020-04-13 23:28:28.363 [INF] CHAN: REORGANIZE: Block 000000000001d9a563b487126986b96858ddca15c7695bb77753a2b8c76833dc is causing a reorganize.
Apr 13 23:28:28 dev-btcd btcd[1514]: fatal error: sync: Unlock of unlocked RWMutex
Apr 13 23:28:28 dev-btcd btcd[1514]: goroutine 14 [running]:
Apr 13 23:28:28 dev-btcd btcd[1514]: runtime.throw(0xaf9816, 0x20)
Apr 13 23:28:28 dev-btcd btcd[1514]: /usr/lib/golang/src/runtime/panic.go:774 +0x72 fp=0xc001d8cfe0 sp=0xc001d8cfb0 pc=0x430da2
Apr 13 23:28:28 dev-btcd btcd[1514]: sync.throw(0xaf9816, 0x20)
Apr 13 23:28:28 dev-btcd btcd[1514]: /usr/lib/golang/src/runtime/panic.go:760 +0x35 fp=0xc001d8d000 sp=0xc001d8cfe0 pc=0x430d25
Apr 13 23:28:28 dev-btcd btcd[1514]: sync.(*RWMutex).Unlock(0xc00048cafc)
Apr 13 23:28:28 dev-btcd btcd[1514]: /usr/lib/golang/src/sync/rwmutex.go:129 +0xbf fp=0xc001d8d038 sp=0xc001d8d000 pc=0x47e1af
Apr 13 23:28:28 dev-btcd btcd[1514]: runtime.call32(0x0, 0xc3f838, 0xc001d8dc10, 0x800000008)
Apr 13 23:28:28 dev-btcd btcd[1514]: /usr/lib/golang/src/runtime/asm_amd64.s:539 +0x3b fp=0xc001d8d068 sp=0xc001d8d038 pc=0x45e86b
Apr 13 23:28:28 dev-btcd btcd[1514]: panic(0xa8dfa0, 0xc01512bea0)
Apr 13 23:28:28 dev-btcd btcd[1514]: /usr/lib/golang/src/runtime/panic.go:679 +0x1b2 fp=0xc001d8d0f8 sp=0xc001d8d068 pc=0x4308e2
Apr 13 23:28:28 dev-btcd btcd[1514]: runtime.goPanicIndex(0xffffffffffffffff, 0x19)
Apr 13 23:28:28 dev-btcd btcd[1514]: /usr/lib/golang/src/runtime/panic.go:75 +0xa3 fp=0xc001d8d140 sp=0xc001d8d0f8 pc=0x42efb3
Apr 13 23:28:28 dev-btcd btcd[1514]: github.com/btcsuite/btcd/mempool.(*FeeEstimator).RegisterBlock(0xc0000d2000, 0xc00e8fc8c0, 0x0, 0x0)
Apr 13 23:28:28 dev-btcd systemd[1]: btcd.service: main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 13 23:28:28 dev-btcd systemd[1]: btcd.service: control process exited, code=exited status=1
Apr 13 23:28:28 dev-btcd systemd[1]: Unit btcd.service entered failed state.
Apr 13 23:28:28 dev-btcd systemd[1]: btcd.service failed.

[Roasbeef]

Came here to make this very issue, thanks for reporting this!

Looking at the stack trace, it's some possible edge case with a double-unlock in the mempool fee estimation code. I've scanned this section a few times before and found proper mutex usage, but possibly there's an edge case in the call graph when a block is being detached, and then attached.

[Roasbeef]

Chatted with davec about this on IRC, and it may be the case that the mutex unlock isn't the true culprit, instead there's a true panic that's being over shadowed by that one.

[Roasbeef]

Closing this as we're tracking the fix here in this comment: #1660 (comment)