Geth DB corruption for gcmode=archive

[vbecas]

Hi there,

3 days ago all my Geth instances (6 of them) running in gcmode=archive were corrupted. Nodes that were running with fastmode=full were unaffected.

I was unable to just restart Geth, so I restored it from a backup and let it catch up with the chain. Unfortunately, after 2 days of syncing, I got the same bug.

PS: I also tried syncing with an older Geth version (i.e v.1.8.1 and 1.7.3) without any luck.

System information

Geth version: 1.8.6 and older
OS & Version: Linux
Commit hash : (if develop)

(128GB RAM with 32cores and 4TB ssd)

Expected behaviour

Geth should sync

Actual behaviour

Geth crashes

Backtrace

INFO [04-30|02:48:56] Imported new chain segment blocks=15 txs=1689 mgas=97.669 elapsed=8.217s mgasps=11.886 number=5528514 hash=0c644d…c6a4d8 cache=0.00B
panic: runtime error: index out of range [recovered]
panic: runtime error: index out of range [recovered]
panic: runtime error: index out of range

goroutine 15 [running]:
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).mCompaction.func1(0xc82582df28, 0xc4202c84e0)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:741 +0xf1
panic(0xdd05a0, 0x17601a0)
/home/travis/.gimme/versions/go1.10.linux.amd64/src/runtime/panic.go:505 +0x229
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).compactionTransact.func1(0x108d780, 0xcc4c83b150, 0xc4202c84e0, 0xc581c5f0b0, 0xc)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:158 +0x1a9
panic(0xdd05a0, 0x17601a0)
/home/travis/.gimme/versions/go1.10.linux.amd64/src/runtime/panic.go:505 +0x229
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.shortenb(0x100d14b2d84, 0x4, 0xc82582d4a8)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/util.go:30 +0x136
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*version).computeCompaction(0xc5835aa0a0)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/version.go:395 +0x47a
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*versionStaging).finish(0xc82582d7a0, 0xc6c5006000)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/version.go:510 +0x893
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*version).spawn(0xc866248410, 0xc6c5006000, 0xc866248410)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/version.go:279 +0x63
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*session).commit(0xc4200f9600, 0xc6c5006000, 0x0, 0x0)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/session.go:195 +0x7e
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).compactionCommit.func1(0xc581c5f0c0, 0xc5835aa001, 0xc581c5f0c0)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:263 +0x37
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*compactionTransactFunc).run(0xcc4c83b150, 0xc581c5f0c0, 0x108d780, 0xcc4c83b150)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:241 +0x33
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).compactionTransact(0xc4202c84e0, 0xc581c5f0b0, 0xc, 0x108d780, 0xcc4c83b150)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:185 +0x162
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).compactionTransactFunc(0xc4202c84e0, 0xc581c5f0b0, 0xc, 0xc5835a4340, 0x0)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:252 +0x88
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).compactionCommit(0xc4202c84e0, 0xf097a3, 0x5, 0xc6c5006000)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:262 +0x11e
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).memCompaction(0xc4202c84e0)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:322 +0x4a5
github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).mCompaction(0xc4202c84e0)
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db_compaction.go:755 +0x81
created by github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.openDB
/home/travis/gopath/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db.go:149 +0x649

[ryanschneider]

I can confirm that we had several 1.7.3 nodes hit what appears to be the same issue over the weekend (but none of our 1.8.x seem to have been effected).

Unfortunately the logs rolled over because it kept trying to restart, so I don't have the original panic, but do have the panic that occurs when trying to restart:

Apr 30 18:52:07 ip-10-0-24-218 systemd[1]: Started Geth.
Apr 30 18:52:07 ip-10-0-24-218 geth[8238]: WARN [04-30|18:52:07] No etherbase set and no accounts found as default
Apr 30 18:52:07 ip-10-0-24-218 geth[8238]: INFO [04-30|18:52:07] Starting peer-to-peer node               instance=Geth/v1.7.3-stable-4bb3c89d/linux-amd64/go1.9
Apr 30 18:52:07 ip-10-0-24-218 geth[8238]: INFO [04-30|18:52:07] Allocated cache and file handles         database=/mnt/chainsnap/ethereum/geth/chaindata cache=2048 handles=1024
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: panic: runtime error: index out of range
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: goroutine 1 [running]:
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.shortenb(0x1004ec0105d, 0x4, 0xc4204c79f8)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/util.go:30 +0x14d
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*version).computeCompaction(0xc4287e40f0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/version.go:395 +0x4b3
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*versionStaging).finish(0xc4204c7d18, 0xc4201f2000)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/version.go:510 +0x935
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*version).spawn(0xc4201b80f0, 0xc4201f2000, 0xc4201b80f0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/version.go:279 +0x7a
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*session).commit(0xc4201d6240, 0xc4201f2000, 0x0, 0x0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/session.go:195 +0x88
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.(*DB).recoverJournal(0xc42016ed80, 0xc42016ed80, 0xc42006c660)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db.go:538 +0xdb8
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.openDB(0xc4201d6240, 0x0, 0x0, 0xc4201d6240)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db.go:122 +0x6ba
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.Open(0x185f540, 0xc42020e700, 0xc4204c82f0, 0x0, 0x0, 0x0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db.go:194 +0x100
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb.OpenFile(0xc420238ea0, 0x26, 0xc4204c82f0, 0xc4201d3be0, 0x4, 0x4)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/github.com/syndtr/goleveldb/leveldb/db.go:216 +0x97
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/ethdb.NewLDBDatabase(0xc420238ea0, 0x26, 0x800, 0x400, 0x26, 0x0, 0x0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/ethdb/database.go:72 +0x363
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/node.(*ServiceContext).OpenDatabase(0xc4202acd80, 0xf4ab0c, 0x9, 0x800, 0x400, 0x0, 0x0, 0x0, 0x0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/node/service.go:46 +0x133
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/eth.CreateDB(0xc4202acd80, 0xc4201f0800, 0xf4ab0c, 0x9, 0x0, 0x0, 0x0, 0x0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/eth/backend.go:201 +0x5d
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/eth.New(0xc4202acd80, 0xc4201f0800, 0x181e560, 0xc4204cd808, 0x417388)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/eth/backend.go:111 +0x93
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/cmd/utils.RegisterEthService.func2(0xc4202acd80, 0xc420172570, 0xc4204cdb18, 0x0, 0xc4201725a0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/cmd/utils/flags.go:1065 +0x3d
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/node.(*Node).Start(0xc4201fe480, 0x0, 0x0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/node/node.go:175 +0x433
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/cmd/utils.StartNode(0xc4201fe480)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/cmd/utils/cmd.go:62 +0x2f
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: main.startNode(0xc42023a840, 0xc4201fe480)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/cmd/geth/main.go:225 +0x43
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: main.geth(0xc42023a840, 0xffb990, 0xb2d05e00)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/cmd/geth/main.go:215 +0x43
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/gopkg.in/urfave/cli%2ev1.HandleAction(0xdd0020, 0xffce18, 0xc42023a840, 0xc42023a840, 0xc4204cdf40)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/gopkg.in/urfave/cli.v1/app.go:490 +0xd2
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: github.com/ethereum/go-ethereum/vendor/gopkg.in/urfave/cli%2ev1.(*App).Run(0xc42025a000, 0xc420010140, 0x14, 0x14, 0x0, 0x0)
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/vendor/gopkg.in/urfave/cli.v1/app.go:264 +0x635
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]: main.main()
Apr 30 18:52:49 ip-10-0-24-218 geth[8238]:         /build/ethereum-ZSPmrv/ethereum-1.7.3+build11486+xenial/build/_workspace/src/github.com/ethereum/go-ethereum/cmd/geth/main.go:204 +0x55

If there's anything I can capture from the chaindata that would help pinpoint what caused this please let me know.

[tstranex]

We're seeing the same issue.

The panic itself seems to be caused by a trivial bug in the leveldb code: https://github.com/ethereum/go-ethereum/blob/master/vendor/github.com/syndtr/goleveldb/leveldb/util.go#L30
If bytes is > 1 TB, then i = 4, which is out of range of bunits.

[ryanschneider]

Thanks @tstranex for finding the fix! If anyone needs a branch with his fix vendored in you can use this one, it's just 1.8.6 with leveled vendored from his PR, and an update to the version.go to correctly identify it as patched.

https://github.com/ryanschneider/go-ethereum/tree/leveldb-patch-186

Hopefully 1.8.7 gets released ASAP, even if the leveled team is slow to accept the PR. /cc @karalabe and @holiman

I guess this also means geth is the first consumer of goleveldb to have a 1TB db? 🎉..?